On Thu, 17 Sep 2020 11:13:47 -0700
Axel Rasmussen <[email protected]> wrote:
> +/*
> + * Trace calls must be in a separate file, as otherwise there's a circuclar
> + * dependency between linux/mmap_lock.h and trace/events/mmap_lock.h.
> + */
> +
> +static void trace_start_locking(struct mm_struct *mm, bool write)
Please don't use "trace_" for functions, as that should be reserved for the
actual tracepoint functions. Please use "do_trace_" or whatever so there's
no confusion about this being a tracepoint, even if it's just a function
that calls the tracepoint.
> +{
> + TRACE_MMAP_LOCK_EVENT(start_locking, mm, 0, write, true);
> +}
> +
> +static void trace_acquire_returned(struct mm_struct *mm, u64 start_time_ns,
> + bool write, bool success)
> +{
> + TRACE_MMAP_LOCK_EVENT(acquire_returned, mm,
> + sched_clock() - start_time_ns, write, success);
> +}
> +
> +static void trace_released(struct mm_struct *mm, bool write)
> +{
> + TRACE_MMAP_LOCK_EVENT(released, mm, 0, write, true);
> +}
> +
> +static inline void lock_impl(struct mm_struct *mm,
> + void (*lock)(struct rw_semaphore *), bool write)
> +{
> + u64 start_time_ns;
> +
> + trace_start_locking(mm, write);
> + start_time_ns = sched_clock();
> + lock(&mm->mmap_lock);
> + trace_acquire_returned(mm, start_time_ns, write, true);
> +}
> +
Why record the start time and pass it in for return, when this can be done
by simply recording the start and return and then using the timestamps of
the trace events to calculate the duration, offline or as synthetic events:
# cd /sys/kernel/tracing/
# echo 'duration u64 time' > synthetic_events
# echo 'hist:keys=common_pid:ts0=common_timestamp.usecs" > events/mmap_lock/mmap_lock_start_locking/trigger
# echo 'hist:keys=common_pid:dur=common_timestamp.usecs-$ts0:onmatch(mmap_lock.mmap_lock_start_locking).trace(duration,$dur)" > events/mmap_lock/mmap_lock_acquire_returned/trigger
# echo 1 > events/synthetic/duration/enable
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 148/148 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-1613 [007] ...3 3186.431687: duration: time=3
bash-1613 [007] ...3 3186.431722: duration: time=2
bash-1613 [007] ...3 3186.431772: duration: time=2
bash-1613 [001] ...3 3188.372001: duration: time=6
bash-1613 [001] ...3 3188.372324: duration: time=6
bash-1613 [001] ...3 3188.372332: duration: time=4
bash-1613 [001] ...3 3188.373557: duration: time=5
bash-1613 [001] ...3 3188.373595: duration: time=3
cat-1868 [002] ...3 3188.373608: duration: time=8
bash-1613 [001] ...3 3188.373613: duration: time=4
bash-1613 [001] ...3 3188.373635: duration: time=3
cat-1868 [002] ...3 3188.373646: duration: time=4
bash-1613 [001] ...3 3188.373652: duration: time=3
bash-1613 [001] ...3 3188.373669: duration: time=3
# echo 'hist:keys=time' > events/synthetic/duration/trigger
# cat events/synthetic/duration/hist
# event histogram
#
# trigger info: hist:keys=time:vals=hitcount:sort=hitcount:size=2048 [active]
#
{ time: 114 } hitcount: 1
{ time: 15 } hitcount: 1
{ time: 11 } hitcount: 1
{ time: 21 } hitcount: 1
{ time: 10 } hitcount: 1
{ time: 46 } hitcount: 1
{ time: 29 } hitcount: 1
{ time: 13 } hitcount: 2
{ time: 16 } hitcount: 3
{ time: 9 } hitcount: 3
{ time: 8 } hitcount: 3
{ time: 7 } hitcount: 8
{ time: 6 } hitcount: 10
{ time: 5 } hitcount: 28
{ time: 4 } hitcount: 121
{ time: 1 } hitcount: 523
{ time: 3 } hitcount: 581
{ time: 2 } hitcount: 882
Totals:
Hits: 2171
Entries: 18
Dropped: 0
And with this I could do a bunch of things like stack trace on max hits and
other features that the tracing histograms give us.
-- Steve
On Thu, Sep 17, 2020 at 12:43 PM Steven Rostedt <[email protected]> wrote:
>
> On Thu, 17 Sep 2020 11:13:47 -0700
> Axel Rasmussen <[email protected]> wrote:
>
> > +/*
> > + * Trace calls must be in a separate file, as otherwise there's a circuclar
> > + * dependency between linux/mmap_lock.h and trace/events/mmap_lock.h.
> > + */
> > +
> > +static void trace_start_locking(struct mm_struct *mm, bool write)
>
> Please don't use "trace_" for functions, as that should be reserved for the
> actual tracepoint functions. Please use "do_trace_" or whatever so there's
> no confusion about this being a tracepoint, even if it's just a function
> that calls the tracepoint.
Done; I'll send a v2 with this change.
>
> > +{
> > + TRACE_MMAP_LOCK_EVENT(start_locking, mm, 0, write, true);
> > +}
> > +
> > +static void trace_acquire_returned(struct mm_struct *mm, u64 start_time_ns,
> > + bool write, bool success)
> > +{
> > + TRACE_MMAP_LOCK_EVENT(acquire_returned, mm,
> > + sched_clock() - start_time_ns, write, success);
> > +}
> > +
> > +static void trace_released(struct mm_struct *mm, bool write)
> > +{
> > + TRACE_MMAP_LOCK_EVENT(released, mm, 0, write, true);
> > +}
> > +
>
> > +static inline void lock_impl(struct mm_struct *mm,
> > + void (*lock)(struct rw_semaphore *), bool write)
> > +{
> > + u64 start_time_ns;
> > +
> > + trace_start_locking(mm, write);
> > + start_time_ns = sched_clock();
> > + lock(&mm->mmap_lock);
> > + trace_acquire_returned(mm, start_time_ns, write, true);
> > +}
> > +
>
> Why record the start time and pass it in for return, when this can be done
> by simply recording the start and return and then using the timestamps of
> the trace events to calculate the duration, offline or as synthetic events:
First, thanks for the detailed feedback! As a newbie this is very helpful. :)
I agree in principle, and I almost have a working version as you
suggest, but I can't see a way to get string fields working.
I believe in trace event headers the typical way to define a string
field is as a "const char *", with the __string, __assign_str, and
__get_str helpers. But, from reading trace_events_synth.c, this isn't
really supported, in that it only supports "char []". But, the hist
trigger code just does a strcmp() of the type string, it doesn't do
any type conversion, so it considers these types incompatible:
After this:
# echo 'mmap_lock_latency u64 time; char memcg_path[256]' >
/sys/kernel/tracing/synthetic_events
Trying to setup the hist trigger gives (the ^ points to the beginning
of keys=>m<emcg_path ... not sure the formatting will be preserved
properly in e-mail):
# cat /sys/kernel/tracing/error_log
[ 15.823725] hist:mmap_lock:mmap_lock_acquire_returned: error: Param
type doesn't match synthetic event field type
Command: hist:keys=memcg_path:latency=common_timestamp.usecs-$ts0:onmatch(mmap_lock.mmap_lock_start_locking).mmap_lock_latency($latency,memcg_path)
^
I tried grepping "char [^\[]+\[" in include/trace/events/, and it
seems nobody is defining fixed-length string fields like that, so I
think that's the wrong solution. I checked the docs about defining
variables (https://www.kernel.org/doc/html/v5.2/trace/histogram.html)
and it doesn't support anything complex like a cast, just - and +.
Any advice?
>
>
> # cd /sys/kernel/tracing/
> # echo 'duration u64 time' > synthetic_events
> # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs" > events/mmap_lock/mmap_lock_start_locking/trigger
> # echo 'hist:keys=common_pid:dur=common_timestamp.usecs-$ts0:onmatch(mmap_lock.mmap_lock_start_locking).trace(duration,$dur)" > events/mmap_lock/mmap_lock_acquire_returned/trigger
> # echo 1 > events/synthetic/duration/enable
> # cat trace
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 148/148 #P:8
> #
> # _-----=> irqs-off
> # / _----=> need-resched
> # | / _---=> hardirq/softirq
> # || / _--=> preempt-depth
> # ||| / delay
> # TASK-PID CPU# |||| TIMESTAMP FUNCTION
> # | | | |||| | |
> bash-1613 [007] ...3 3186.431687: duration: time=3
> bash-1613 [007] ...3 3186.431722: duration: time=2
> bash-1613 [007] ...3 3186.431772: duration: time=2
> bash-1613 [001] ...3 3188.372001: duration: time=6
> bash-1613 [001] ...3 3188.372324: duration: time=6
> bash-1613 [001] ...3 3188.372332: duration: time=4
> bash-1613 [001] ...3 3188.373557: duration: time=5
> bash-1613 [001] ...3 3188.373595: duration: time=3
> cat-1868 [002] ...3 3188.373608: duration: time=8
> bash-1613 [001] ...3 3188.373613: duration: time=4
> bash-1613 [001] ...3 3188.373635: duration: time=3
> cat-1868 [002] ...3 3188.373646: duration: time=4
> bash-1613 [001] ...3 3188.373652: duration: time=3
> bash-1613 [001] ...3 3188.373669: duration: time=3
>
> # echo 'hist:keys=time' > events/synthetic/duration/trigger
> # cat events/synthetic/duration/hist
> # event histogram
> #
> # trigger info: hist:keys=time:vals=hitcount:sort=hitcount:size=2048 [active]
> #
>
> { time: 114 } hitcount: 1
> { time: 15 } hitcount: 1
> { time: 11 } hitcount: 1
> { time: 21 } hitcount: 1
> { time: 10 } hitcount: 1
> { time: 46 } hitcount: 1
> { time: 29 } hitcount: 1
> { time: 13 } hitcount: 2
> { time: 16 } hitcount: 3
> { time: 9 } hitcount: 3
> { time: 8 } hitcount: 3
> { time: 7 } hitcount: 8
> { time: 6 } hitcount: 10
> { time: 5 } hitcount: 28
> { time: 4 } hitcount: 121
> { time: 1 } hitcount: 523
> { time: 3 } hitcount: 581
> { time: 2 } hitcount: 882
>
> Totals:
> Hits: 2171
> Entries: 18
> Dropped: 0
>
> And with this I could do a bunch of things like stack trace on max hits and
> other features that the tracing histograms give us.
>
> -- Steve
On Fri, 18 Sep 2020 13:26:37 -0700
Axel Rasmussen <[email protected]> wrote:
> On Thu, Sep 17, 2020 at 12:43 PM Steven Rostedt <[email protected]> wrote:
> >
> > On Thu, 17 Sep 2020 11:13:47 -0700
> > Axel Rasmussen <[email protected]> wrote:
> >
> > > +/*
> > > + * Trace calls must be in a separate file, as otherwise there's a circuclar
> > > + * dependency between linux/mmap_lock.h and trace/events/mmap_lock.h.
> > > + */
> > > +
> > > +static void trace_start_locking(struct mm_struct *mm, bool write)
> >
> > Please don't use "trace_" for functions, as that should be reserved for the
> > actual tracepoint functions. Please use "do_trace_" or whatever so there's
> > no confusion about this being a tracepoint, even if it's just a function
> > that calls the tracepoint.
>
> Done; I'll send a v2 with this change.
>
> >
> > > +{
> > > + TRACE_MMAP_LOCK_EVENT(start_locking, mm, 0, write, true);
> > > +}
> > > +
> > > +static void trace_acquire_returned(struct mm_struct *mm, u64 start_time_ns,
> > > + bool write, bool success)
> > > +{
> > > + TRACE_MMAP_LOCK_EVENT(acquire_returned, mm,
> > > + sched_clock() - start_time_ns, write, success);
> > > +}
> > > +
> > > +static void trace_released(struct mm_struct *mm, bool write)
> > > +{
> > > + TRACE_MMAP_LOCK_EVENT(released, mm, 0, write, true);
> > > +}
> > > +
> >
> > > +static inline void lock_impl(struct mm_struct *mm,
> > > + void (*lock)(struct rw_semaphore *), bool write)
> > > +{
> > > + u64 start_time_ns;
> > > +
> > > + trace_start_locking(mm, write);
> > > + start_time_ns = sched_clock();
> > > + lock(&mm->mmap_lock);
> > > + trace_acquire_returned(mm, start_time_ns, write, true);
> > > +}
> > > +
> >
> > Why record the start time and pass it in for return, when this can be done
> > by simply recording the start and return and then using the timestamps of
> > the trace events to calculate the duration, offline or as synthetic events:
>
> First, thanks for the detailed feedback! As a newbie this is very helpful. :)
>
> I agree in principle, and I almost have a working version as you
> suggest, but I can't see a way to get string fields working.
>
> I believe in trace event headers the typical way to define a string
> field is as a "const char *", with the __string, __assign_str, and
> __get_str helpers. But, from reading trace_events_synth.c, this isn't
> really supported, in that it only supports "char []". But, the hist
> trigger code just does a strcmp() of the type string, it doesn't do
> any type conversion, so it considers these types incompatible:
>
> After this:
> # echo 'mmap_lock_latency u64 time; char memcg_path[256]' >
> /sys/kernel/tracing/synthetic_events
>
> Trying to setup the hist trigger gives (the ^ points to the beginning
> of keys=>m<emcg_path ... not sure the formatting will be preserved
> properly in e-mail):
> # cat /sys/kernel/tracing/error_log
> [ 15.823725] hist:mmap_lock:mmap_lock_acquire_returned: error: Param
> type doesn't match synthetic event field type
> Command: hist:keys=memcg_path:latency=common_timestamp.usecs-$ts0:onmatch(mmap_lock.mmap_lock_start_locking).mmap_lock_latency($latency,memcg_path)
> ^
>
> I tried grepping "char [^\[]+\[" in include/trace/events/, and it
> seems nobody is defining fixed-length string fields like that, so I
> think that's the wrong solution. I checked the docs about defining
> variables (https://www.kernel.org/doc/html/v5.2/trace/histogram.html)
> and it doesn't support anything complex like a cast, just - and +.
>
> Any advice?
Tom,
Do you think we could make histograms support the above somehow?
-- Steve
>
>
>
> >
> >
> > # cd /sys/kernel/tracing/
> > # echo 'duration u64 time' > synthetic_events
> > # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs" > events/mmap_lock/mmap_lock_start_locking/trigger
> > # echo 'hist:keys=common_pid:dur=common_timestamp.usecs-$ts0:onmatch(mmap_lock.mmap_lock_start_locking).trace(duration,$dur)" > events/mmap_lock/mmap_lock_acquire_returned/trigger
> > # echo 1 > events/synthetic/duration/enable
> > # cat trace
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 148/148 #P:8
> > #
> > # _-----=> irqs-off
> > # / _----=> need-resched
> > # | / _---=> hardirq/softirq
> > # || / _--=> preempt-depth
> > # ||| / delay
> > # TASK-PID CPU# |||| TIMESTAMP FUNCTION
> > # | | | |||| | |
> > bash-1613 [007] ...3 3186.431687: duration: time=3
> > bash-1613 [007] ...3 3186.431722: duration: time=2
> > bash-1613 [007] ...3 3186.431772: duration: time=2
> > bash-1613 [001] ...3 3188.372001: duration: time=6
> > bash-1613 [001] ...3 3188.372324: duration: time=6
> > bash-1613 [001] ...3 3188.372332: duration: time=4
> > bash-1613 [001] ...3 3188.373557: duration: time=5
> > bash-1613 [001] ...3 3188.373595: duration: time=3
> > cat-1868 [002] ...3 3188.373608: duration: time=8
> > bash-1613 [001] ...3 3188.373613: duration: time=4
> > bash-1613 [001] ...3 3188.373635: duration: time=3
> > cat-1868 [002] ...3 3188.373646: duration: time=4
> > bash-1613 [001] ...3 3188.373652: duration: time=3
> > bash-1613 [001] ...3 3188.373669: duration: time=3
> >
> > # echo 'hist:keys=time' > events/synthetic/duration/trigger
> > # cat events/synthetic/duration/hist
> > # event histogram
> > #
> > # trigger info: hist:keys=time:vals=hitcount:sort=hitcount:size=2048 [active]
> > #
> >
> > { time: 114 } hitcount: 1
> > { time: 15 } hitcount: 1
> > { time: 11 } hitcount: 1
> > { time: 21 } hitcount: 1
> > { time: 10 } hitcount: 1
> > { time: 46 } hitcount: 1
> > { time: 29 } hitcount: 1
> > { time: 13 } hitcount: 2
> > { time: 16 } hitcount: 3
> > { time: 9 } hitcount: 3
> > { time: 8 } hitcount: 3
> > { time: 7 } hitcount: 8
> > { time: 6 } hitcount: 10
> > { time: 5 } hitcount: 28
> > { time: 4 } hitcount: 121
> > { time: 1 } hitcount: 523
> > { time: 3 } hitcount: 581
> > { time: 2 } hitcount: 882
> >
> > Totals:
> > Hits: 2171
> > Entries: 18
> > Dropped: 0
> >
> > And with this I could do a bunch of things like stack trace on max hits and
> > other features that the tracing histograms give us.
> >
> > -- Steve
Hi Steve, Axel,
On Fri, 2020-09-18 at 16:41 -0400, Steven Rostedt wrote:
> On Fri, 18 Sep 2020 13:26:37 -0700
> Axel Rasmussen <[email protected]> wrote:
>
> > On Thu, Sep 17, 2020 at 12:43 PM Steven Rostedt <
> > [email protected]> wrote:
> > >
> > > On Thu, 17 Sep 2020 11:13:47 -0700
> > > Axel Rasmussen <[email protected]> wrote:
> > >
> > > > +/*
> > > > + * Trace calls must be in a separate file, as otherwise
> > > > there's a circuclar
> > > > + * dependency between linux/mmap_lock.h and
> > > > trace/events/mmap_lock.h.
> > > > + */
> > > > +
> > > > +static void trace_start_locking(struct mm_struct *mm, bool
> > > > write)
> > >
> > > Please don't use "trace_" for functions, as that should be
> > > reserved for the
> > > actual tracepoint functions. Please use "do_trace_" or whatever
> > > so there's
> > > no confusion about this being a tracepoint, even if it's just a
> > > function
> > > that calls the tracepoint.
> >
> > Done; I'll send a v2 with this change.
> >
> > >
> > > > +{
> > > > + TRACE_MMAP_LOCK_EVENT(start_locking, mm, 0, write, true);
> > > > +}
> > > > +
> > > > +static void trace_acquire_returned(struct mm_struct *mm, u64
> > > > start_time_ns,
> > > > + bool write, bool success)
> > > > +{
> > > > + TRACE_MMAP_LOCK_EVENT(acquire_returned, mm,
> > > > + sched_clock() - start_time_ns,
> > > > write, success);
> > > > +}
> > > > +
> > > > +static void trace_released(struct mm_struct *mm, bool write)
> > > > +{
> > > > + TRACE_MMAP_LOCK_EVENT(released, mm, 0, write, true);
> > > > +}
> > > > +
> > >
> > >
> > > > +static inline void lock_impl(struct mm_struct *mm,
> > > > + void (*lock)(struct rw_semaphore *),
> > > > bool write)
> > > > +{
> > > > + u64 start_time_ns;
> > > > +
> > > > + trace_start_locking(mm, write);
> > > > + start_time_ns = sched_clock();
> > > > + lock(&mm->mmap_lock);
> > > > + trace_acquire_returned(mm, start_time_ns, write, true);
> > > > +}
> > > > +
> > >
> > > Why record the start time and pass it in for return, when this
> > > can be done
> > > by simply recording the start and return and then using the
> > > timestamps of
> > > the trace events to calculate the duration, offline or as
> > > synthetic events:
> >
> > First, thanks for the detailed feedback! As a newbie this is very
> > helpful. :)
> >
> > I agree in principle, and I almost have a working version as you
> > suggest, but I can't see a way to get string fields working.
> >
> > I believe in trace event headers the typical way to define a string
> > field is as a "const char *", with the __string, __assign_str, and
> > __get_str helpers. But, from reading trace_events_synth.c, this
> > isn't
> > really supported, in that it only supports "char []". But, the hist
> > trigger code just does a strcmp() of the type string, it doesn't do
> > any type conversion, so it considers these types incompatible:
> >
> > After this:
> > # echo 'mmap_lock_latency u64 time; char memcg_path[256]' >
> > /sys/kernel/tracing/synthetic_events
> >
> > Trying to setup the hist trigger gives (the ^ points to the
> > beginning
> > of keys=>m<emcg_path ... not sure the formatting will be preserved
> > properly in e-mail):
> > # cat /sys/kernel/tracing/error_log
> > [ 15.823725] hist:mmap_lock:mmap_lock_acquire_returned: error:
> > Param
> > type doesn't match synthetic event field type
> > Command: hist:keys=memcg_path:latency=common_timestamp.usecs-
> > $ts0:onmatch(mmap_lock.mmap_lock_start_locking).mmap_lock_latency($
> > latency,memcg_path)
> > ^
> >
> > I tried grepping "char [^\[]+\[" in include/trace/events/, and it
> > seems nobody is defining fixed-length string fields like that, so I
> > think that's the wrong solution. I checked the docs about defining
> > variables (
> > https://www.kernel.org/doc/html/v5.2/trace/histogram.html)
> > and it doesn't support anything complex like a cast, just - and +.
> >
> > Any advice?
>
> Tom,
>
> Do you think we could make histograms support the above somehow?
>
Sorry for the delayed reply - was out on vacation.
Yeah, currently the synthetic events only support constant-length
strings, which should match with __array()s in the tracepoints, but I
think they should also be made to support variable-length arrays that
would match __string() etc.
I'm thinking an array field without length specifier could be used to
in the synthetic event specification for that e.g.:
# echo 'mmap_lock_latency u64 time; char memcg_path[]' > /sys/kernel/tracing/synthetic_events
I'll work on adding that over the next couple days or so...
Tom
> -- Steve
>
> >
> >
> >
> > >
> > >
> > > # cd /sys/kernel/tracing/
> > > # echo 'duration u64 time' > synthetic_events
> > > # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs" >
> > > events/mmap_lock/mmap_lock_start_locking/trigger
> > > # echo 'hist:keys=common_pid:dur=common_timestamp.usecs-
> > > $ts0:onmatch(mmap_lock.mmap_lock_start_locking).trace(duration,$d
> > > ur)" > events/mmap_lock/mmap_lock_acquire_returned/trigger
> > > # echo 1 > events/synthetic/duration/enable
> > > # cat trace
> > > # tracer: nop
> > > #
> > > # entries-in-buffer/entries-written: 148/148 #P:8
> > > #
> > > # _-----=> irqs-off
> > > # / _----=> need-resched
> > > # | / _---=> hardirq/softirq
> > > # || / _--=> preempt-depth
> > > # ||| / delay
> > > # TASK-PID CPU# |||| TIMESTAMP FUNCTION
> > > # | | | |||| | |
> > > bash-1613 [007] ...3 3186.431687: duration: time=3
> > > bash-1613 [007] ...3 3186.431722: duration: time=2
> > > bash-1613 [007] ...3 3186.431772: duration: time=2
> > > bash-1613 [001] ...3 3188.372001: duration: time=6
> > > bash-1613 [001] ...3 3188.372324: duration: time=6
> > > bash-1613 [001] ...3 3188.372332: duration: time=4
> > > bash-1613 [001] ...3 3188.373557: duration: time=5
> > > bash-1613 [001] ...3 3188.373595: duration: time=3
> > > cat-1868 [002] ...3 3188.373608: duration: time=8
> > > bash-1613 [001] ...3 3188.373613: duration: time=4
> > > bash-1613 [001] ...3 3188.373635: duration: time=3
> > > cat-1868 [002] ...3 3188.373646: duration: time=4
> > > bash-1613 [001] ...3 3188.373652: duration: time=3
> > > bash-1613 [001] ...3 3188.373669: duration: time=3
> > >
> > > # echo 'hist:keys=time' > events/synthetic/duration/trigger
> > > # cat events/synthetic/duration/hist
> > > # event histogram
> > > #
> > > # trigger info:
> > > hist:keys=time:vals=hitcount:sort=hitcount:size=2048 [active]
> > > #
> > >
> > > { time: 114 } hitcount: 1
> > > { time: 15 } hitcount: 1
> > > { time: 11 } hitcount: 1
> > > { time: 21 } hitcount: 1
> > > { time: 10 } hitcount: 1
> > > { time: 46 } hitcount: 1
> > > { time: 29 } hitcount: 1
> > > { time: 13 } hitcount: 2
> > > { time: 16 } hitcount: 3
> > > { time: 9 } hitcount: 3
> > > { time: 8 } hitcount: 3
> > > { time: 7 } hitcount: 8
> > > { time: 6 } hitcount: 10
> > > { time: 5 } hitcount: 28
> > > { time: 4 } hitcount: 121
> > > { time: 1 } hitcount: 523
> > > { time: 3 } hitcount: 581
> > > { time: 2 } hitcount: 882
> > >
> > > Totals:
> > > Hits: 2171
> > > Entries: 18
> > > Dropped: 0
> > >
> > > And with this I could do a bunch of things like stack trace on
> > > max hits and
> > > other features that the tracing histograms give us.
> > >
> > > -- Steve
>
>