Dropped Events

Dropped Events

[Michael Sartain]

We are doing some fairly simple ftrace captures using trace-cmd and we're
missing chunks of events. We are starting the trace via something like ~ this:

    trace-cmd record -i -k -b 2000 -o $startTrace__traceFile \
        -e "amdgpu:amdgpu_vm_flush" -e "amdgpu:amdgpu_cs_ioctl" \
        -e "amdgpu:amdgpu_sched_run_job" -e "drm:drm_vblank_event" \
        -e "*fence:*fence_signaled" -e "amdgpu:amdgpu_ttm_bo_move" \
        -e "sched:sched_switch" &

And then the capture is done with a kill -9 $(pidof trace-cmd)

We've tried not capturing sched_switch events (which were about 75% of the
events), but we are still seeing missing events such as the drm_vblank events
(81 - 85) in the example below [1]. "trace-cmd report --stat" reports 0 dropped
events, no overruns, etc.

I'm going to try and set up a repro case and debug what's going on, but before
doing that I thought I would ask here since I've seen two places online mention
dropped events [2,3] and was wondering if there was more information on this.
Ie, is this expected behavior? Is it logged anywhere? Any way to mitigate?

Thanks much.
 -Mike

[1] trace-cmd report trace.dat | grep drm_vblank_event
....
 <idle>-0 [001] 537337.235498: drm_vblank_event: crtc=0 seq=31330580
 <idle>-0 [001] 537337.302508: drm_vblank_event: crtc=0 seq=31330586
 <idle>-0 [001] 537337.313674: drm_vblank_event: crtc=0 seq=31330587
 <idle>-0 [001] 537337.324862: drm_vblank_event: crtc=0 seq=31330588
 <idle>-0 [001] 537337.336011: drm_vblank_event: crtc=0 seq=31330589
 <idle>-0 [001] 537337.347189: drm_vblank_event: crtc=0 seq=31330590
 <idle>-0 [001] 537337.358352: drm_vblank_event: crtc=0 seq=31330591
 <idle>-0 [001] 537337.369535: drm_vblank_event: crtc=0 seq=31330592
 <idle>-0 [001] 537337.380688: drm_vblank_event: crtc=0 seq=31330593


[2] https://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg02326.html

> Actually one thing that came to mind that I would like to clarification about.
> I know that tracepoints are “lossy” and that if the “reader” of the pipe is not
> consuming fast enough and the ring buffers get full then tracepoint information
> gets dropped and pipe logs that it lost events. When I run “perf record”, is it
> also recording every tracepoint or is it sampling (which I don’t exactly
> understand but I think of it as it just periodically captures the tracepoint
> info which basically means it’s losing them intentionally)?

[3] http://codearcana.com/posts/2016/01/03/dtrace-isnt-just-a-tool-its-a-philosophy.html

> Unfortunately, tracing all scheduler events is very high overhead in perf and
> the lack of in-kernel aggregation means that events probably will be dropped if
> load is high.

Re: Dropped Events

[Arnaldo Carvalho de Melo]

Em Thu, Oct 26, 2017 at 11:21:07AM -0600, Michael Sartain escreveu:
> We are doing some fairly simple ftrace captures using trace-cmd and we're
> missing chunks of events. We are starting the trace via something like ~ this:
> 
>     trace-cmd record -i -k -b 2000 -o $startTrace__traceFile \
>         -e "amdgpu:amdgpu_vm_flush" -e "amdgpu:amdgpu_cs_ioctl" \
>         -e "amdgpu:amdgpu_sched_run_job" -e "drm:drm_vblank_event" \
>         -e "*fence:*fence_signaled" -e "amdgpu:amdgpu_ttm_bo_move" \
>         -e "sched:sched_switch" &
> 
> And then the capture is done with a kill -9 $(pidof trace-cmd)

Can you try with the equivalent 'perf record' (or perf trace) call?

[root@jouet ~]# perf record -m 16384 -e i915:intel_gpu_freq_change,drm:drm_vblank_event,fence*:*fence_signaled,sched:sched_switch^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 2.792 MB perf.data (2895 samples) ]

[root@jouet ~]#

It'll report lost events, replace the i915 with the amdgpu events.

- Arnaldo
 
> We've tried not capturing sched_switch events (which were about 75% of the
> events), but we are still seeing missing events such as the drm_vblank events
> (81 - 85) in the example below [1]. "trace-cmd report --stat" reports 0 dropped
> events, no overruns, etc.
> 
> I'm going to try and set up a repro case and debug what's going on, but before
> doing that I thought I would ask here since I've seen two places online mention
> dropped events [2,3] and was wondering if there was more information on this.
> Ie, is this expected behavior? Is it logged anywhere? Any way to mitigate?
> 
> Thanks much.
>  -Mike
> 
> [1] trace-cmd report trace.dat | grep drm_vblank_event
> ....
>  <idle>-0 [001] 537337.235498: drm_vblank_event: crtc=0 seq=31330580
>  <idle>-0 [001] 537337.302508: drm_vblank_event: crtc=0 seq=31330586
>  <idle>-0 [001] 537337.313674: drm_vblank_event: crtc=0 seq=31330587
>  <idle>-0 [001] 537337.324862: drm_vblank_event: crtc=0 seq=31330588
>  <idle>-0 [001] 537337.336011: drm_vblank_event: crtc=0 seq=31330589
>  <idle>-0 [001] 537337.347189: drm_vblank_event: crtc=0 seq=31330590
>  <idle>-0 [001] 537337.358352: drm_vblank_event: crtc=0 seq=31330591
>  <idle>-0 [001] 537337.369535: drm_vblank_event: crtc=0 seq=31330592
>  <idle>-0 [001] 537337.380688: drm_vblank_event: crtc=0 seq=31330593
> 
> 
> [2] https://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg02326.html
> 
> > Actually one thing that came to mind that I would like to clarification about.
> > I know that tracepoints are “lossy” and that if the “reader” of the pipe is not
> > consuming fast enough and the ring buffers get full then tracepoint information
> > gets dropped and pipe logs that it lost events. When I run “perf record”, is it
> > also recording every tracepoint or is it sampling (which I don’t exactly
> > understand but I think of it as it just periodically captures the tracepoint
> > info which basically means it’s losing them intentionally)?
> 
> [3] http://codearcana.com/posts/2016/01/03/dtrace-isnt-just-a-tool-its-a-philosophy.html
> 
> > Unfortunately, tracing all scheduler events is very high overhead in perf and
> > the lack of in-kernel aggregation means that events probably will be dropped if
> > load is high.
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Dropped Events

[Michael Sartain]

On Thu, Oct 26, 2017 at 05:18:38PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Thu, Oct 26, 2017 at 11:21:07AM -0600, Michael Sartain escreveu:
> > We are doing some fairly simple ftrace captures using trace-cmd and we're
> > missing chunks of events. We are starting the trace via something like ~ this:
> > 
> >     trace-cmd record -i -k -b 2000 -o $startTrace__traceFile \
> >         -e "amdgpu:amdgpu_vm_flush" -e "amdgpu:amdgpu_cs_ioctl" \
> >         -e "amdgpu:amdgpu_sched_run_job" -e "drm:drm_vblank_event" \
> >         -e "*fence:*fence_signaled" -e "amdgpu:amdgpu_ttm_bo_move" \
> >         -e "sched:sched_switch" &
> > 
> > And then the capture is done with a kill -9 $(pidof trace-cmd)
> 
> Can you try with the equivalent 'perf record' (or perf trace) call?
> 
> [root@jouet ~]# perf record -m 16384 -e i915:intel_gpu_freq_change,drm:drm_vblank_event,fence*:*fence_signaled,sched:sched_switch^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 2.792 MB perf.data (2895 samples) ]
> 
> [root@jouet ~]#
> 
> It'll report lost events, replace the i915 with the amdgpu events.

Hi Arnaldo.

Sorry for the delay, got busy doing some other work and took a while to
narrow down a repro case that didn't involve running games and VR
compositors, etc.

I did the following on my Dell XPS i7-6560U laptop with Debian Test 4.13.4-2.

1. Ran: glxgears -fullscreen
2: Ran: sudo perf record -m 16384 -e sched:sched_switch -e sched:sched_process_fork -e sched:sched_process_exec
     -e sched:sched_process_exit -e drm:drm_vblank_event -e drm:drm_vblank_event_queued -e *fence:*fence_signaled
     -e i915:i915_flip_request -e i915:i915_flip_complete -e i915:intel_gpu_freq_change -e i915:i915_gem_request_add
     -e i915:intel_engine_notify -e i915:i915_gem_request_wait_begin -e i915:i915_gem_request_wait_end

  << ... waited ~30 seconds ... >>
^C
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 10.466 MB perf.data (85200 samples) ]

Everything worked as expected in this case. The below is a repro for ~ what
we're seeing with the loaded system.

1. Ran: glxgears -fullscreen
2: Ran: sudo perf record -m 16384 -e sched:sched_switch -e sched:sched_process_fork -e sched:sched_process_exec
     -e sched:sched_process_exit -e drm:drm_vblank_event -e drm:drm_vblank_event_queued -e *fence:*fence_signaled
     -e i915:i915_flip_request -e i915:i915_flip_complete -e i915:intel_gpu_freq_change -e i915:i915_gem_request_add
     -e i915:intel_engine_notify -e i915:i915_gem_request_wait_begin -e i915:i915_gem_request_wait_end
3. Ran: dd oflag=direct if=/home/mikesart/test.tmp of=/home/mikesart/test2.tmp bs=4k count=2000000 && sync
     where test.tmp is a ~7.7G file

  << ... waited ~30 seconds ... >>
^C
[ perf record: Woken up 4 times to write data ]
[ perf record: Captured and wrote 165.687 MB perf.data (1359800 samples) ]

For this case we wound up with a 165MB perf.data file. This is the same
behavior we're seeing with trace-cmd. No reported missing events or anything,
and a huge trace.dat file with missing chunks of events.

Thanks.
 -Mike