Re: Why systemtap loses events and what can be done about it?

[Brad Peters <bpeters at linux dot vnet dot ibm dot com>]

Frank Ch. Eigler wrote:
> Hi -
> 
> On Tue, Sep 04, 2007 at 09:48:13AM -0700, Mike Mason wrote:
> 
>> Mike Mason wrote:
>> I've been toying with the idea of optimizing probe handlers by
>> implementing them like interrupt handlers, with top and bottom
>> halves.  [...]
> 
> This is unlikely to be faster overall, but is an interesting idea.
> Putting blocking-capable constructs into a deferred-work handler could
> be an explicit option, though wrought with risks.  (Lack of
> synchronization is one: a deferred get_user() value may not resemble
> one possibly fetched at the instant of a raw probe point.)
> 
> - FChE
We earlier had the discussion on splitting a probe handler into a split handler,
one of which occurs when the probe is hit and interrupts are disabled, the other
of which occurs at some time later (decided by the kernel using work queue
heuristics).  From this discussion, I mentioned I would assess possible time
savings gained via this approach.  I've done so, using a work-queue based async
copy method, with the following results.

In order to make valid estimates, I broke the sequence of events down as follows.

Scenario 1: Current approach
1. Interrupts are disabled
2. Data is collected
3. Data is parsed/analyzed/modified
4. Data is then written across a relayfs channel to user-space
5. Handler exits, Interrupts are enabled

Scenario 2: Split paradigm
1. Interrupts are disabled
2. Data is collected
3. Work-queue event is scheduled
4. Routine exits, Interrupts are enabled
5. Data is modified and written to relay sometime later


As each of these measurements was taken while interrupts were disabled, timing
shown here is equivalent to both wall clock time and CPU time.

Scenario 1.
Steps 2 and 3: Approx 3-40 microseconds, with the upper bound reached when 		
register values are being collected.
Step 4: Approx. 3-4 u.sec, consistently, regardless of data volume (within
normal usage levels, 100-1500 bytes of data were typically seen per-write)

Scenario 2.
Step 2: 3-4 u.sec.  All number crunching was moved into the bottom-half
Step 3: 3 u.sec.
Step 5: Doesn't matter... interrupts are enabled.

Best regards,

Brad Peters
bpeters@linux.vnet.ibm.com
LTC, IBM