| Message ID | 20210915195306.612966-1-kaleshsingh@google.com |
|---|---|
| Headers | show |
| Series | tracing: Extend histogram triggers expression parsing | expand |
Hi Kalesh, On Wed, Sep 15, 2021 at 1:09 PM Kalesh Singh <kaleshsingh@google.com> wrote: > > On Wed, Sep 15, 2021 at 12:53 PM Kalesh Singh <kaleshsingh@google.com> wrote: > > > > The frequency of the rss_stat trace event is known to be of the same > > magnitude as that of the sched_switch event on Android devices. This can > > cause flooding of the trace buffer with rss_stat traces leading to a > > decreased trace buffer capacity and loss of data. > > > > If it is not necessary to monitor very small changes in rss (as is the > > case in Android) then the rss_stat tracepoint can be throttled to only > > emit the event once there is a large enough change in the rss size. > > The original patch that introduced the rss_stat tracepoint also proposed > > a fixed throttling mechanism that only emits the rss_stat event > > when the rss size crosses a 512KB boundary. It was concluded that more > > generic support for this type of filtering/throttling was need, so that > > it can be applied to any trace event. [1] > > > > From the discussion in [1], histogram triggers seemed the most likely > > candidate to support this type of throttling. For instance to achieve the > > same throttling as was proposed in [1]: > > > > (1) Create a histogram variable to save the 512KB bucket of the rss size > > (2) Use the onchange handler to generate a synthetic event when the > > rss size bucket changes. > > > > The only missing pieces to support such a hist trigger are: > > (1) Support for setting a hist variable to a specific value -- to set > > the bucket size / granularity. > > (2) Support for division arithmetic operation -- to determine the > > corresponding bucket for an rss size. > > > > This series extends histogram trigger expressions to: > > (1) Allow assigning numeric literals to hist variable (eg. x=1234) > > and using literals directly in expressions (eg. x=size/1234) > > (2) Support division and multiplication in hist expressions. > > (eg. a=$x/$y*z); and > > (3) Fixes expression parsing for non-associative operators: subtraction > > and division. (eg. 8-4-2 should be 2 not 6) > > > > The rss_stat event can then be throttled using histogram triggers as > > below: > > > > # Create a synthetic event to monitor instead of the high frequency > > # rss_stat event > > echo 'rss_stat_throttled unsigned int mm_id; unsigned int curr; > > int member; long size' >> tracing/synthetic_events > > > > # Create a hist trigger that emits the synthetic rss_stat_throttled > > # event only when the rss size crosses a 512KB boundary. > > echo 'hist:keys=common_pid:bucket=size/0x80000:onchange($bucket) > > .rss_stat_throttled(mm_id,curr,member,size)' > > >> events/kmem/rss_stat/trigger > > > > Sorry, I have a clerical mistake here. The above key should be: > s/keys=common_pid/keys=keys=mm_id,member > > The rss size is specific to the mm struct's member not the pid. > The results below were captured with the correct key so no changes there. > > > ------ Test Results ------ > > Histograms can also be used to evaluate the effectiveness of this > > throttling by noting the Total Hits on each trigger: > > > > echo 'hist:keys=common_pid' >> events/sched/sched_switch/trigger > > echo 'hist:keys=common_pid' >> events/kmem/rss_stat/trigger > > echo 'hist:keys=common_pid' > > >> events/synthetic/rss_stat_throttled/trigger > > > > Allowing the above example (512KB granularity) run for 5 minutes on > > an arm64 device with 5.10 kernel: > > > > sched_switch : total hits = 147153 > > rss_stat : total hits = 38863 > > rss_stat_throttled: total hits = 2409 > > > > The synthetic rss_stat_throttled event is ~16x less frequent than the > > rss_stat event when using a 512KB granularity. > > > > > > The results are more pronounced when rss size is changing at a higher > > rate in small increments. For instance the following results were obtained > > by recording the hits on the above events for a run of Android's > > lmkd_unit_test [2], which continually forks processes that map anonymous > > memory until there is an oom kill: > > > > sched_switch : total hits = 148832 > > rss_stat : total hits = 4754802 > > rss_stat_throttled: total hits = 96214 > > > > In this stress this, the synthetic rss_stat_throttled event is ~50x less > > frequent than the rss_stat event when using a 512KB granularity. > > > > > > [1] https://lore.kernel.org/lkml/20190903200905.198642-1-joel@joelfernandes.org/ > > [2] https://cs.android.com/android/platform/superproject/+/master:system/memory/lmkd/tests/lmkd_test.cpp > > > > Signed-off-by: Kalesh Singh <kaleshsingh@google.com> Reviewed-by: Namhyung Kim <namhyung@kernel.org> Thanks, Namhyung > > > > Kalesh Singh (5): > > tracing: Add support for creating hist trigger variables from literal > > tracing: Add division and multiplication support for hist triggers > > tracing: Fix operator precedence for hist triggers expression > > tracing/selftests: Add tests for hist trigger expression parsing > > tracing/histogram: Document expression arithmetic and constants > > > > Documentation/trace/histogram.rst | 14 + > > kernel/trace/trace_events_hist.c | 318 +++++++++++++++--- > > .../testing/selftests/ftrace/test.d/functions | 4 +- > > .../trigger/trigger-hist-expressions.tc | 73 ++++ > > 4 files changed, 357 insertions(+), 52 deletions(-) > > create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc > > > > > > base-commit: 3ca706c189db861b2ca2019a0901b94050ca49d8 > > -- > > 2.33.0.309.g3052b89438-goog > >
On Thu, Sep 30, 2021 at 3:58 PM Namhyung Kim <namhyung@kernel.org> wrote: > > Hi Kalesh, > > On Wed, Sep 15, 2021 at 1:09 PM Kalesh Singh <kaleshsingh@google.com> wrote: > > > > On Wed, Sep 15, 2021 at 12:53 PM Kalesh Singh <kaleshsingh@google.com> wrote: > > > > > > The frequency of the rss_stat trace event is known to be of the same > > > magnitude as that of the sched_switch event on Android devices. This can > > > cause flooding of the trace buffer with rss_stat traces leading to a > > > decreased trace buffer capacity and loss of data. > > > > > > If it is not necessary to monitor very small changes in rss (as is the > > > case in Android) then the rss_stat tracepoint can be throttled to only > > > emit the event once there is a large enough change in the rss size. > > > The original patch that introduced the rss_stat tracepoint also proposed > > > a fixed throttling mechanism that only emits the rss_stat event > > > when the rss size crosses a 512KB boundary. It was concluded that more > > > generic support for this type of filtering/throttling was need, so that > > > it can be applied to any trace event. [1] > > > > > > From the discussion in [1], histogram triggers seemed the most likely > > > candidate to support this type of throttling. For instance to achieve the > > > same throttling as was proposed in [1]: > > > > > > (1) Create a histogram variable to save the 512KB bucket of the rss size > > > (2) Use the onchange handler to generate a synthetic event when the > > > rss size bucket changes. > > > > > > The only missing pieces to support such a hist trigger are: > > > (1) Support for setting a hist variable to a specific value -- to set > > > the bucket size / granularity. > > > (2) Support for division arithmetic operation -- to determine the > > > corresponding bucket for an rss size. > > > > > > This series extends histogram trigger expressions to: > > > (1) Allow assigning numeric literals to hist variable (eg. x=1234) > > > and using literals directly in expressions (eg. x=size/1234) > > > (2) Support division and multiplication in hist expressions. > > > (eg. a=$x/$y*z); and > > > (3) Fixes expression parsing for non-associative operators: subtraction > > > and division. (eg. 8-4-2 should be 2 not 6) > > > > > > The rss_stat event can then be throttled using histogram triggers as > > > below: > > > > > > # Create a synthetic event to monitor instead of the high frequency > > > # rss_stat event > > > echo 'rss_stat_throttled unsigned int mm_id; unsigned int curr; > > > int member; long size' >> tracing/synthetic_events > > > > > > # Create a hist trigger that emits the synthetic rss_stat_throttled > > > # event only when the rss size crosses a 512KB boundary. > > > echo 'hist:keys=common_pid:bucket=size/0x80000:onchange($bucket) > > > .rss_stat_throttled(mm_id,curr,member,size)' > > > >> events/kmem/rss_stat/trigger > > > > > > > Sorry, I have a clerical mistake here. The above key should be: > > s/keys=common_pid/keys=keys=mm_id,member > > > > The rss size is specific to the mm struct's member not the pid. > > The results below were captured with the correct key so no changes there. > > > > > ------ Test Results ------ > > > Histograms can also be used to evaluate the effectiveness of this > > > throttling by noting the Total Hits on each trigger: > > > > > > echo 'hist:keys=common_pid' >> events/sched/sched_switch/trigger > > > echo 'hist:keys=common_pid' >> events/kmem/rss_stat/trigger > > > echo 'hist:keys=common_pid' > > > >> events/synthetic/rss_stat_throttled/trigger > > > > > > Allowing the above example (512KB granularity) run for 5 minutes on > > > an arm64 device with 5.10 kernel: > > > > > > sched_switch : total hits = 147153 > > > rss_stat : total hits = 38863 > > > rss_stat_throttled: total hits = 2409 > > > > > > The synthetic rss_stat_throttled event is ~16x less frequent than the > > > rss_stat event when using a 512KB granularity. > > > > > > > > > The results are more pronounced when rss size is changing at a higher > > > rate in small increments. For instance the following results were obtained > > > by recording the hits on the above events for a run of Android's > > > lmkd_unit_test [2], which continually forks processes that map anonymous > > > memory until there is an oom kill: > > > > > > sched_switch : total hits = 148832 > > > rss_stat : total hits = 4754802 > > > rss_stat_throttled: total hits = 96214 > > > > > > In this stress this, the synthetic rss_stat_throttled event is ~50x less > > > frequent than the rss_stat event when using a 512KB granularity. > > > > > > > > > [1] https://lore.kernel.org/lkml/20190903200905.198642-1-joel@joelfernandes.org/ > > > [2] https://cs.android.com/android/platform/superproject/+/master:system/memory/lmkd/tests/lmkd_test.cpp > > > > > > Signed-off-by: Kalesh Singh <kaleshsingh@google.com> > > Reviewed-by: Namhyung Kim <namhyung@kernel.org> Thanks for the review Namhyung! > > Thanks, > Namhyung > > > > > > > > Kalesh Singh (5): > > > tracing: Add support for creating hist trigger variables from literal > > > tracing: Add division and multiplication support for hist triggers > > > tracing: Fix operator precedence for hist triggers expression > > > tracing/selftests: Add tests for hist trigger expression parsing > > > tracing/histogram: Document expression arithmetic and constants > > > > > > Documentation/trace/histogram.rst | 14 + > > > kernel/trace/trace_events_hist.c | 318 +++++++++++++++--- > > > .../testing/selftests/ftrace/test.d/functions | 4 +- > > > .../trigger/trigger-hist-expressions.tc | 73 ++++ > > > 4 files changed, 357 insertions(+), 52 deletions(-) > > > create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc > > > > > > > > > base-commit: 3ca706c189db861b2ca2019a0901b94050ca49d8 > > > -- > > > 2.33.0.309.g3052b89438-goog > > >