{ "_class" : "hudson.matrix.MatrixBuild", "actions" : [ { "_class" : "hudson.model.CauseAction", "causes" : [ { "_class" : "org.jenkinsci.plugins.ghprb.GhprbCause", "shortDescription" : "GitHub pull request #3227 of commit f0dba496eefdf4170c19c83fc9fbd22d38488215, no merge conflicts." } ] }, { "_class" : "org.jenkinsci.plugins.ghprb.GhprbParametersAction", "parameters" : [ { "_class" : "hudson.model.StringParameterValue", "name" : "sha1", "value" : "origin/pr/3227/merge" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbActualCommit", "value" : "f0dba496eefdf4170c19c83fc9fbd22d38488215" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbActualCommitAuthor", "value" : "" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbActualCommitAuthorEmail", "value" : "" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbAuthorRepoGitUrl", "value" : "https://github.com/kawamuray/bcc.git" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbTriggerAuthor", "value" : "" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbTriggerAuthorEmail", "value" : "" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbTriggerAuthorLogin", "value" : "yonghong-song" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbTriggerAuthorLoginMention", "value" : "@yonghong-song" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbPullId", "value" : "3227" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbTargetBranch", "value" : "master" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbSourceBranch", "value" : "offcputime-negative-time" }, { "_class" : "hudson.model.StringParameterValue", "name" : "GIT_BRANCH", "value" : "offcputime-negative-time" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbPullAuthorEmail", "value" : "" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbPullAuthorLogin", "value" : "kawamuray" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbPullAuthorLoginMention", "value" : "@kawamuray" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbPullDescription", "value" : "GitHub pull request #3227 of commit f0dba496eefdf4170c19c83fc9fbd22d38488215, no merge conflicts." }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbPullTitle", "value" : "tools/offcputime Filter out negative offcpu duration" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbPullLink", "value" : "https://github.com/iovisor/bcc/pull/3227" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbPullLongDescription", "value" : "I 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 -0 [002] d... 3548378.357934: : Clock regression!: 4257954648 > 4256982417\\r\\n -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\\n" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbCommentBody", "value" : "[buildbot, test this please]" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbGhRepository", "value" : "iovisor/bcc" }, { "_class" : "hudson.model.StringParameterValue", "name" : "ghprbCredentialsId", "value" : "6d3daf13-69b8-48b1-9c8f-ec5353264113" } ] }, { "_class" : "hudson.plugins.git.GitTagAction" }, { }, { }, { "_class" : "org.jenkinsci.plugins.displayurlapi.actions.RunDisplayAction" } ], "artifacts" : [ ], "building" : False, "description" : "PR #3227: tools/offcputime Filter out...", "displayName" : "#807", "duration" : 1236058, "estimatedDuration" : 7460664, "executor" : None, "fullDisplayName" : "bcc-pr #807", "id" : "807", "keepLog" : False, "number" : 807, "queueId" : 6465, "result" : "SUCCESS", "timestamp" : 1610696608662, "url" : "https://buildbot.iovisor.org/jenkins/job/bcc-pr/807/", "builtOn" : "", "changeSet" : { "_class" : "hudson.plugins.git.GitChangeSetList", "items" : [ ], "kind" : "git" }, "culprits" : [ ], "runs" : [ { "number" : 807, "url" : "https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=fc25/807/" }, { "number" : 807, "url" : "https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=fc26/807/" }, { "number" : 807, "url" : "https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=fc27/807/" }, { "number" : 807, "url" : "https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=fc28/807/" }, { "number" : 807, "url" : "https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=ubuntu1604/807/" }, { "number" : 807, "url" : "https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=ubuntu1710/807/" }, { "number" : 807, "url" : "https://buildbot.iovisor.org/jenkins/job/bcc-pr/label=ubuntu1804/807/" } ] }