GitHub pull request #3227 of commit f0dba496eefdf4170c19c83fc9fbd22d38488215, no merge conflicts.sha1origin/pr/3227/mergeghprbActualCommitf0dba496eefdf4170c19c83fc9fbd22d38488215ghprbActualCommitAuthorghprbActualCommitAuthorEmailghprbAuthorRepoGitUrlhttps://github.com/kawamuray/bcc.gitghprbTriggerAuthorghprbTriggerAuthorEmailghprbTriggerAuthorLoginyonghong-songghprbTriggerAuthorLoginMention@yonghong-songghprbPullId3227ghprbTargetBranchmasterghprbSourceBranchoffcputime-negative-timeGIT_BRANCHoffcputime-negative-timeghprbPullAuthorEmailghprbPullAuthorLoginkawamurayghprbPullAuthorLoginMention@kawamurayghprbPullDescriptionGitHub pull request #3227 of commit f0dba496eefdf4170c19c83fc9fbd22d38488215, no merge conflicts.ghprbPullTitletools/offcputime Filter out negative offcpu durationghprbPullLinkhttps://github.com/iovisor/bcc/pull/3227ghprbPullLongDescriptionI think the current `offcputime.py` counts not only events properly filtered in but also some events with short duration due to regressing value from `bpf_ktime_get_ns()`.\r\n\r\nbcc version: latest on git\r\nkernel version: CentOS7, 3.10.0-1127.18.2.el7\r\n\r\n\r\n## Background\r\n\r\nI was developing my own version of offcputime.py that produces events for each long offcpu event including duration of the task stayed off-cpu.\r\nAfter getting some samples, I realized that in some cases duration (`u64 delta = bpf_ktime_get_ns() - *tsp`) is insanely large number and figured out that it is due to negative numbers printed as unsigned 64bit.\r\n\r\n## Reproducing the issue\r\n\r\nI thought there should be the same issue exists in `offcputime.py` and modified it as below:\r\n\r\n```diff\r\ndiff --git a/tools/offcputime.py b/tools/offcputime.py\r\nindex 068c7076..11d8a4d8 100755\r\n--- a/tools/offcputime.py\r\n+++ b/tools/offcputime.py\r\n@@ -146,7 +146,12 @@ int oncpu(struct pt_regs *ctx, struct task_struct *prev) {\r\n }\r\n \r\n // calculate current thread's delta time\r\n- u64 delta = bpf_ktime_get_ns() - *tsp;\r\n+ u64 t_start = *tsp;\r\n+ u64 t_end = bpf_ktime_get_ns();\r\n+ if (t_start > t_end) {\r\n+ bpf_trace_printk(\"Clock regression!: %u > %u\\n\", t_start, t_end);\r\n+ }\r\n+ u64 delta = t_end - t_start;\r\n start.delete(&pid);\r\n delta = delta / 1000;\r\n if ((delta < MINBLOCK_US) || (delta > MAXBLOCK_US)) {\r\n@@ -246,6 +251,7 @@ if not folded:\r\n else:\r\n print(\"... Hit Ctrl-C to end.\")\r\n \r\n+b.trace_print()\r\n try:\r\n sleep(duration)\r\n except KeyboardInterrupt:\r\n```\r\n\r\nAs I executed the modified version on my system, I could confirm that there are some events with negative delta (the time stored in `start` > current time).\r\n\r\n```\r\n$ ~/offcputime.py -m 100000 3\r\nTracing off-CPU time (us) of all threads by user + kernel stack for 3 secs.\r\n <...>-123820 [000] d... 3548318.327993: : Clock regression!: 59599178 > 59567229\r\n <...>-76871 [000] d... 3548330.825545: : Clock regression!: 3968610353 > 3967622873\r\n <...>-123810 [000] d... 3548353.203783: : Clock regression!: 577745979 > 576818764\r\n <idle>-0 [002] d... 3548378.357934: : Clock regression!: 4257954648 > 4256982417\r\n <idle>-0 [003] d... 3548404.022071: : Clock regression!: 4153185458 > 4152188905\r\n```\r\n\r\n## Cause\r\n\r\nI think this is caused by regressing return value from `bpf_ktime_get_ns()`, which calls `ktime_get_mono_fast_ns`. The document of `ktime_get_mono_fast_ns` actually [states it isn't guaranteed to always return monotonic value](https://github.com/torvalds/linux/blob/65f0d2414b7079556fbbcc070b3d1c9f9587606d/kernel/time/timekeeping.c#L456).\r\n\r\n## Proposed fix\r\n\r\nJust filter out cases where the end time is larger than the start time. I assume such cases happen only when the actual duration between last off-cpu and on-cpu is short, so I think it's better than accidentally counting them in.\r\nghprbCommentBody[buildbot, test this please]ghprbGhRepositoryiovisor/bccghprbCredentialsId6d3daf13-69b8-48b1-9c8f-ec5353264113false<a title="tools/offcputime Filter out negative offcpu duration" href="https://github.com/iovisor/bcc/pull/3227">PR #3227</a>: tools/offcputime Filter out...#80712360587460664bcc-pr #807807false8076465SUCCESS1610696608662https://buildbot.iovisor.org/jenkins/job/bcc-pr/807/git807https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=fc25/807/807https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=fc26/807/807https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=fc27/807/807https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=fc28/807/807https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=ubuntu1604/807/807https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=ubuntu1710/807/807https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=ubuntu1804/807/