| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Sat, 2 Jul 2022 17:35:31 +0800
From: Yang Jihong <yangjihong1@...wei.com>
To: <mingo@...hat.com>, <acme@...nel.org>, <mark.rutland@....com>,
<alexander.shishkin@...ux.intel.com>, <jolsa@...nel.org>,
<namhyung@...nel.org>, <ast@...nel.org>, <daniel@...earbox.net>,
<andrii@...nel.org>, <john.fastabend@...il.com>,
<kpsingh@...nel.org>, <irogers@...gle.com>,
<linux-kernel@...r.kernel.org>, <linux-perf-users@...r.kernel.org>
CC: <adrian.hunter@...el.com>, <alexandre.truong@....com>,
<davemarchevsky@...com>, <yhs@...com>, <songliubraving@...com>,
<kafai@...com>, <peterz@...radead.org>, <bpf@...r.kernel.org>,
<netdev@...r.kernel.org>
Subject: Re: [RFC v2 00/17] perf: Add perf kwork
Hello,
On 2022/6/24 22:03, Yang Jihong wrote:
> Sometimes, we need to analyze time properties of kernel work such as irq,
> softirq, and workqueue, including delay and running time of specific interrupts.
> Currently, these events have kernel tracepoints, but perf tool does not
> directly analyze the delay of these events
>
> The perf-kwork tool is used to trace time properties of kernel work
> (such as irq, softirq, and workqueue), including runtime, latency,
> and timehist, using the infrastructure in the perf tools to allow
> tracing extra targets
>
> We also use bpf trace to collect and filter data in kernel to solve
> problem of large perf data volume and extra file system interruptions.
>
> Example usage:
>
> 1. Kwork record:
>
> # perf kwork record -- sleep 10
> [ perf record: Woken up 0 times to write data ]
> [ perf record: Captured and wrote 6.825 MB perf.data ]
>
> 2. Kwork report:
>
> # perf kwork report -S
>
> Kwork Name | Cpu | Total Runtime | Count | Max runtime | Max runtime start | Max runtime end |
> --------------------------------------------------------------------------------------------------------------------------------
> virtio0-requests:25 | 0000 | 1347.861 ms | 25049 | 1.417 ms | 121235.524083 s | 121235.525499 s |
> (s)TIMER:1 | 0005 | 151.033 ms | 2545 | 0.153 ms | 121237.454591 s | 121237.454744 s |
> (s)RCU:9 | 0005 | 117.254 ms | 2754 | 0.223 ms | 121239.461024 s | 121239.461246 s |
> (s)SCHED:7 | 0005 | 58.714 ms | 1773 | 0.075 ms | 121237.702345 s | 121237.702419 s |
> (s)RCU:9 | 0007 | 43.359 ms | 945 | 0.861 ms | 121237.702984 s | 121237.703845 s |
> (s)SCHED:7 | 0000 | 33.389 ms | 549 | 4.121 ms | 121235.521379 s | 121235.525499 s |
> (s)RCU:9 | 0002 | 21.419 ms | 484 | 0.281 ms | 121244.629001 s | 121244.629282 s |
> (w)mix_interrupt_randomness | 0000 | 21.047 ms | 391 | 1.016 ms | 121237.934008 s | 121237.935024 s |
> (s)SCHED:7 | 0007 | 19.903 ms | 570 | 0.065 ms | 121235.523360 s | 121235.523426 s |
> (s)RCU:9 | 0000 | 19.017 ms | 472 | 0.507 ms | 121244.634002 s | 121244.634510 s |
> ... <SNIP> ...
> (s)SCHED:7 | 0003 | 0.049 ms | 1 | 0.049 ms | 121240.018631 s | 121240.018680 s |
> (w)vmstat_update | 0003 | 0.046 ms | 1 | 0.046 ms | 121240.916200 s | 121240.916246 s |
> (s)RCU:9 | 0004 | 0.045 ms | 2 | 0.024 ms | 121235.522876 s | 121235.522900 s |
> (w)neigh_managed_work | 0001 | 0.044 ms | 1 | 0.044 ms | 121235.513929 s | 121235.513973 s |
> (w)vmstat_update | 0006 | 0.031 ms | 1 | 0.031 ms | 121245.673914 s | 121245.673945 s |
> (w)vmstat_update | 0004 | 0.028 ms | 1 | 0.028 ms | 121235.522743 s | 121235.522770 s |
> (w)wb_update_bandwidth_workfn | 0000 | 0.024 ms | 1 | 0.024 ms | 121244.842660 s | 121244.842683 s |
> --------------------------------------------------------------------------------------------------------------------------------
> Total count : 36071
> Total runtime (msec) : 1887.188 (0.185% load average)
> Total time span (msec) : 10185.012
> --------------------------------------------------------------------------------------------------------------------------------
>
> 3. Kwork latency:
>
> # perf kwork latency
>
> Kwork Name | Cpu | Avg delay | Count | Max delay | Max delay start | Max delay end |
> --------------------------------------------------------------------------------------------------------------------------------
> (s)TIMER:1 | 0004 | 3.903 ms | 1 | 3.903 ms | 121235.517068 s | 121235.520971 s |
> (s)RCU:9 | 0004 | 3.252 ms | 2 | 5.809 ms | 121235.517068 s | 121235.522876 s |
> (s)RCU:9 | 0001 | 3.238 ms | 2 | 5.832 ms | 121235.514494 s | 121235.520326 s |
> (w)vmstat_update | 0004 | 1.738 ms | 1 | 1.738 ms | 121235.521005 s | 121235.522743 s |
> (s)SCHED:7 | 0004 | 0.978 ms | 2 | 1.899 ms | 121235.520940 s | 121235.522840 s |
> (w)wb_update_bandwidth_workfn | 0000 | 0.834 ms | 1 | 0.834 ms | 121244.841826 s | 121244.842660 s |
> (s)RCU:9 | 0003 | 0.479 ms | 3 | 0.752 ms | 121240.027521 s | 121240.028273 s |
> (s)TIMER:1 | 0001 | 0.465 ms | 1 | 0.465 ms | 121235.513107 s | 121235.513572 s |
> (w)vmstat_update | 0000 | 0.391 ms | 5 | 1.275 ms | 121236.814938 s | 121236.816213 s |
> (w)mix_interrupt_randomness | 0002 | 0.317 ms | 5 | 0.874 ms | 121244.628034 s | 121244.628908 s |
> (w)neigh_managed_work | 0001 | 0.315 ms | 1 | 0.315 ms | 121235.513614 s | 121235.513929 s |
> ... <SNIP> ...
> (s)TIMER:1 | 0005 | 0.061 ms | 2545 | 0.506 ms | 121237.136113 s | 121237.136619 s |
> (s)SCHED:7 | 0001 | 0.052 ms | 21 | 0.437 ms | 121237.711014 s | 121237.711451 s |
> (s)SCHED:7 | 0002 | 0.045 ms | 309 | 0.145 ms | 121237.137184 s | 121237.137329 s |
> (s)SCHED:7 | 0003 | 0.045 ms | 1 | 0.045 ms | 121240.018586 s | 121240.018631 s |
> (s)SCHED:7 | 0007 | 0.044 ms | 570 | 0.173 ms | 121238.161161 s | 121238.161334 s |
> (s)BLOCK:4 | 0003 | 0.030 ms | 4 | 0.056 ms | 121240.028255 s | 121240.028311 s |
> --------------------------------------------------------------------------------------------------------------------------------
> INFO: 28.761% skipped events (27674 including 2607 raise, 25067 entry, 0 exit)
>
> 4. Kwork timehist:
>
> # perf kwork timehist
> Runtime start Runtime end Cpu Kwork name Runtime Delaytime
> (TYPE)NAME:NUM (msec) (msec)
> ----------------- ----------------- ------ ------------------------------ ---------- ----------
> 121235.513572 121235.513674 [0001] (s)TIMER:1 0.102 0.465
> 121235.513688 121235.513738 [0001] (s)SCHED:7 0.050 0.172
> 121235.513750 121235.513777 [0001] (s)RCU:9 0.027 0.643
> 121235.513929 121235.513973 [0001] (w)neigh_managed_work 0.044 0.315
> 121235.520326 121235.520386 [0001] (s)RCU:9 0.060 5.832
> 121235.520672 121235.520716 [0002] (s)SCHED:7 0.044 0.048
> 121235.520729 121235.520753 [0002] (s)RCU:9 0.024 5.651
> 121235.521213 121235.521249 [0005] (s)TIMER:1 0.036 0.064
> 121235.520166 121235.521379 [0000] (s)SCHED:7 1.213 0.056
> ... <SNIP> ...
> 121235.533256 121235.533296 [0000] virtio0-requests:25 0.040
> 121235.533322 121235.533359 [0000] (s)SCHED:7 0.037 0.095
> 121235.533018 121235.533452 [0006] (s)RCU:9 0.434 0.348
> 121235.534653 121235.534698 [0000] virtio0-requests:25 0.046
> 121235.535657 121235.535702 [0000] virtio0-requests:25 0.044
> 121235.535857 121235.535916 [0005] (s)TIMER:1 0.059 0.055
> 121235.535927 121235.535947 [0005] (s)RCU:9 0.020 0.113
> 121235.536178 121235.536196 [0006] (s)RCU:9 0.018 0.410
> 121235.537406 121235.537445 [0006] (s)SCHED:7 0.039 0.049
> 121235.537457 121235.537481 [0006] (s)RCU:9 0.024 0.334
> 121235.538199 121235.538254 [0007] (s)RCU:9 0.055 0.066
>
> 5. Kwork report use bpf:
>
> # perf kwork report -b
> Starting trace, Hit <Ctrl+C> to stop and report
> ^C
> Kwork Name | Cpu | Total Runtime | Count | Max runtime | Max runtime start | Max runtime end |
> --------------------------------------------------------------------------------------------------------------------------------
> (w)flush_to_ldisc | 0000 | 2.279 ms | 2 | 2.219 ms | 121293.080933 s | 121293.083152 s |
> (s)SCHED:7 | 0001 | 2.141 ms | 2 | 2.100 ms | 121293.082064 s | 121293.084164 s |
> (s)RCU:9 | 0003 | 2.137 ms | 3 | 2.046 ms | 121293.081348 s | 121293.083394 s |
> (s)TIMER:1 | 0007 | 1.882 ms | 12 | 0.249 ms | 121295.632211 s | 121295.632460 s |
> (w)e1000_watchdog | 0002 | 1.136 ms | 3 | 0.428 ms | 121294.496559 s | 121294.496987 s |
> (s)SCHED:7 | 0007 | 0.995 ms | 12 | 0.139 ms | 121295.632483 s | 121295.632621 s |
> (s)NET_RX:3 | 0002 | 0.727 ms | 5 | 0.391 ms | 121299.044624 s | 121299.045016 s |
> (s)TIMER:1 | 0002 | 0.696 ms | 5 | 0.164 ms | 121294.496172 s | 121294.496337 s |
> (s)SCHED:7 | 0002 | 0.427 ms | 6 | 0.077 ms | 121295.840321 s | 121295.840398 s |
> (s)SCHED:7 | 0000 | 0.366 ms | 3 | 0.156 ms | 121296.545389 s | 121296.545545 s |
> eth0:10 | 0002 | 0.353 ms | 5 | 0.122 ms | 121293.084796 s | 121293.084919 s |
> (w)flush_to_ldisc | 0000 | 0.298 ms | 1 | 0.298 ms | 121299.046236 s | 121299.046534 s |
> (w)mix_interrupt_randomness | 0002 | 0.215 ms | 4 | 0.077 ms | 121293.086747 s | 121293.086823 s |
> (s)RCU:9 | 0002 | 0.128 ms | 3 | 0.060 ms | 121293.087348 s | 121293.087409 s |
> (w)vmstat_shepherd | 0000 | 0.098 ms | 1 | 0.098 ms | 121293.083901 s | 121293.083999 s |
> (s)TIMER:1 | 0001 | 0.089 ms | 1 | 0.089 ms | 121293.085709 s | 121293.085798 s |
> (w)vmstat_update | 0003 | 0.071 ms | 1 | 0.071 ms | 121293.085227 s | 121293.085298 s |
> (w)wq_barrier_func | 0000 | 0.064 ms | 1 | 0.064 ms | 121293.083688 s | 121293.083752 s |
> (w)vmstat_update | 0000 | 0.041 ms | 1 | 0.041 ms | 121293.083829 s | 121293.083869 s |
> (s)RCU:9 | 0001 | 0.038 ms | 1 | 0.038 ms | 121293.085818 s | 121293.085856 s |
> (s)RCU:9 | 0007 | 0.035 ms | 1 | 0.035 ms | 121293.112322 s | 121293.112357 s |
> --------------------------------------------------------------------------------------------------------------------------------
>
> 6. Kwork latency use bpf:
>
> # perf kwork latency -b
> Starting trace, Hit <Ctrl+C> to stop and report
> ^C
> Kwork Name | Cpu | Avg delay | Count | Max delay | Max delay start | Max delay end |
> --------------------------------------------------------------------------------------------------------------------------------
> (w)vmstat_shepherd | 0000 | 2.044 ms | 2 | 2.764 ms | 121314.942758 s | 121314.945522 s |
> (w)flush_to_ldisc | 0000 | 1.008 ms | 1 | 1.008 ms | 121317.335508 s | 121317.336516 s |
> (w)vmstat_update | 0002 | 0.879 ms | 1 | 0.879 ms | 121317.024405 s | 121317.025284 s |
> (w)mix_interrupt_randomness | 0002 | 0.328 ms | 5 | 0.383 ms | 121308.832944 s | 121308.833327 s |
> (w)e1000_watchdog | 0002 | 0.304 ms | 5 | 0.368 ms | 121317.024305 s | 121317.024673 s |
> (s)RCU:9 | 0001 | 0.172 ms | 41 | 0.728 ms | 121308.308187 s | 121308.308915 s |
> (s)TIMER:1 | 0000 | 0.149 ms | 3 | 0.195 ms | 121317.334255 s | 121317.334449 s |
> (s)NET_RX:3 | 0001 | 0.143 ms | 40 | 1.213 ms | 121315.030992 s | 121315.032205 s |
> (s)RCU:9 | 0002 | 0.139 ms | 27 | 0.187 ms | 121315.077388 s | 121315.077576 s |
> (s)NET_RX:3 | 0002 | 0.130 ms | 7 | 0.283 ms | 121308.832917 s | 121308.833201 s |
> (s)SCHED:7 | 0007 | 0.123 ms | 34 | 0.191 ms | 121308.736240 s | 121308.736431 s |
> (s)TIMER:1 | 0007 | 0.116 ms | 18 | 0.145 ms | 121308.736168 s | 121308.736313 s |
> (s)RCU:9 | 0007 | 0.111 ms | 68 | 0.318 ms | 121308.736194 s | 121308.736512 s |
> (s)SCHED:7 | 0002 | 0.110 ms | 22 | 0.292 ms | 121308.832197 s | 121308.832489 s |
> (s)TIMER:1 | 0001 | 0.107 ms | 1 | 0.107 ms | 121314.948230 s | 121314.948337 s |
> (w)neigh_managed_work | 0001 | 0.103 ms | 1 | 0.103 ms | 121314.948381 s | 121314.948484 s |
> (s)RCU:9 | 0000 | 0.099 ms | 49 | 0.289 ms | 121308.520167 s | 121308.520456 s |
> (s)NET_RX:3 | 0007 | 0.096 ms | 40 | 1.227 ms | 121315.022994 s | 121315.024220 s |
> (s)RCU:9 | 0003 | 0.093 ms | 37 | 0.261 ms | 121314.950651 s | 121314.950913 s |
> (w)flush_to_ldisc | 0000 | 0.090 ms | 1 | 0.090 ms | 121317.336737 s | 121317.336827 s |
> (s)TIMER:1 | 0002 | 0.078 ms | 36 | 0.115 ms | 121310.880172 s | 121310.880288 s |
> (s)SCHED:7 | 0001 | 0.071 ms | 27 | 0.180 ms | 121314.953571 s | 121314.953751 s |
> (s)SCHED:7 | 0000 | 0.066 ms | 28 | 0.344 ms | 121317.334345 s | 121317.334689 s |
> (s)SCHED:7 | 0003 | 0.063 ms | 14 | 0.119 ms | 121314.978808 s | 121314.978927 s |
> --------------------------------------------------------------------------------------------------------------------------------
>
> 7. Kwork report with filter:
>
> # perf kwork report -b -n RCU
> Starting trace, Hit <Ctrl+C> to stop and report
> ^C
> Kwork Name | Cpu | Total Runtime | Count | Max runtime | Max runtime start | Max runtime end |
> --------------------------------------------------------------------------------------------------------------------------------
> (s)RCU:9 | 0006 | 2.266 ms | 3 | 2.158 ms | 121335.008290 s | 121335.010449 s |
> (s)RCU:9 | 0002 | 0.158 ms | 3 | 0.063 ms | 121335.011914 s | 121335.011977 s |
> (s)RCU:9 | 0007 | 0.082 ms | 1 | 0.082 ms | 121335.448378 s | 121335.448460 s |
> (s)RCU:9 | 0000 | 0.058 ms | 1 | 0.058 ms | 121335.011350 s | 121335.011408 s |
> --------------------------------------------------------------------------------------------------------------------------------
>
PING
Looking forward to the community's review
Best Regards,
Yang
Powered by blists - more mailing lists