Do not query CPU data when querying process data #845

dandavison · 2021-12-10T02:40:16Z

@th1000s @ttys3 This branch uses the (unmerged and unreleased) branch of sysinfo from GuillaumeGomez/sysinfo#634 to avoid querying for CPU data when we query for process data. The commit here is on top of @th1000s's PR #841 which reduces the number of processes queried.

Can either of you confirm that this commit fixes the CPU slowness problem, and indeed that there are no slowness problems at all on this branch? cc @unphased @infokiller

Fixes #839
Ref GuillaumeGomez/sysinfo#632

unphased · 2021-12-10T04:02:51Z

I just tested this and it made a different binary but same behavior as 0.11.2 of spending 0.6s waiting on my 32 thread CPU. How can I confirm with cargo that the correct version of the dependency is being pulled? (Edit: I cargo clean and cargo build --release a second time, it built a bit-identical binary compared to my incremental build)

❯ cargo build --release     
    Updating git repository `https://github.com/GuillaumeGomez/sysinfo`
   Compiling sysinfo v0.21.2 (https://github.com/GuillaumeGomez/sysinfo?branch=specific-process-update#6354be73)
   Compiling git-delta v0.11.2 (/home/slu/delta)
    Finished release [optimized] target(s) in 6.69s

❯ time diff -u <(echo abc) <(echo bcd) | delta         

/proc/self/fd/15:1:
  1¦   │abc
   ¦  1│bcd
diff -u <(echo abc) <(echo bcd)  0.00s user 0.01s system 97% cpu 0.007 total
delta  0.04s user 0.01s system 7% cpu 0.648 total

❯ l  
total 29332
-rwxrwxr-x  1 slu slu     2003 Jul  6 19:45 showterm
-rwxrwxr-x  1 slu slu  9962152 Dec  3 12:28 delta_0.10.3
-rwxrwxr-x  2 slu slu 10017912 Dec  9 22:57 delta_0.11.2
-rwxrwxr-x  2 slu slu 10030592 Dec  9 23:00 delta
drwxrwxr-x  2 slu slu     4096 Dec  9 23:00 .
drwxr-xr-x 84 slu slu    12288 Dec  9 23:02 ..

I tried spawning 10k sleeps and ~~as expected~~, the 0.10.3 version takes over 1 second while all others take 0.65s so the process scanning issue is gone but this branch doesnt seem to have improved anything on the cpu freq testing front.

I'm a bit confused because when I tested 100k sleep processes even 0.10.3 did not slow down much more. And strace output volume went from 69k lines to 102k lines, which is not what I expected. So something is slightly fishy about the process searching, but that's water under the bridge I suppose.

dandavison · 2021-12-10T04:54:42Z

Hm. Just to ask a silly question -- when you pipe to "delta" it's definitely picking up the intended executable?

unphased · 2021-12-10T05:13:57Z

Yes confirmed.

ttys3 · 2021-12-10T05:58:46Z

confirmed, sysinfo-processrefreshkind branch code did not resolve the slowdown problem.

here's the compare result (a 6 core machine):

delta version 0.11.2 result: > 130ms

do
   sleep 1
   time /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta Cargo.toml.bak Cargo.toml > /dev/null
done
 /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta  Cargo.toml  0.04s user 0.01s system 41% cpu 0.135 total
 /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta  Cargo.toml  0.05s user 0.01s system 41% cpu 0.136 total
 /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta  Cargo.toml  0.05s user 0.01s system 54% cpu 0.106 total
 /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta  Cargo.toml  0.06s user 0.00s system 100% cpu 0.058 total
 /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta  Cargo.toml  0.05s user 0.01s system 41% cpu 0.136 total
 /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta  Cargo.toml  0.06s user 0.00s system 61% cpu 0.093 total
 /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta  Cargo.toml  0.05s user 0.01s system 47% cpu 0.118 total
 /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta  Cargo.toml  0.05s user 0.01s system 40% cpu 0.138 total
 /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta  Cargo.toml  0.05s user 0.00s system 39% cpu 0.145 total
 /tmp/delta-0.11.2-x86_64-unknown-linux-gnu/delta  Cargo.toml  0.05s user 0.00s system 41% cpu 0.136 total

release build from sysinfo-processrefreshkind branch result: > 130ms

for (( c=1; c<=10; c++ ))
do
   sleep 1
   time /tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml > /dev/null
done
/tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml >   0.04s user 0.02s system 42% cpu 0.140 total
/tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml >   0.05s user 0.01s system 42% cpu 0.138 total
/tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml >   0.05s user 0.00s system 40% cpu 0.142 total
/tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml >   0.05s user 0.01s system 45% cpu 0.125 total
/tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml >   0.05s user 0.00s system 50% cpu 0.112 total
/tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml >   0.05s user 0.00s system 101% cpu 0.056 total
/tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml >   0.06s user 0.00s system 57% cpu 0.107 total
/tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml >   0.05s user 0.00s system 41% cpu 0.136 total
/tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml >   0.04s user 0.02s system 63% cpu 0.089 total
/tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml >   0.05s user 0.01s system 40% cpu 0.139 total

as a compare, here is my patched version (binary here: https://github.com/ttys3/delta/releases/tag/0.11.2) time cost:

result: > 70ms

the code: https://github.com/ttys3/delta/tree/sysinfo-v0.19.2-linux-perf

❯ for (( c=1; c<=10; c++ ))
do
   sleep 1
   time  /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null
done
 /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null  0.05s user 0.02s system 77% cpu 0.085 total
 /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null  0.06s user 0.01s system 80% cpu 0.078 total
 /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null  0.05s user 0.01s system 82% cpu 0.075 total
 /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null  0.06s user 0.00s system 81% cpu 0.077 total
 /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null  0.05s user 0.01s system 101% cpu 0.061 total
 /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null  0.05s user 0.01s system 80% cpu 0.079 total
 /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null  0.06s user 0.01s system 81% cpu 0.076 total
 /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null  0.05s user 0.01s system 73% cpu 0.085 total
 /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null  0.05s user 0.01s system 82% cpu 0.076 total
 /tmp/delta Cargo.toml.bak Cargo.toml > /dev/null  0.05s user 0.01s system 82% cpu 0.075 to

ttys3 · 2021-12-10T06:53:37Z

with strace /tmp/branch-sysinfo-processrefreshkind/delta Cargo.toml.bak Cargo.toml I got the result shows that it did read
/sys/devices/system/cpu/cpuX/cpufreq/scaling_cur_freq

munmap(0x7f732f45f000, 36864)           = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
close(7)                                = 0
read(5, "diff --git a/Cargo.toml.bak b/Ca"..., 8192) = 827
write(6, "\n", 1)                       = 1

write(6, "\33[", 2�[)                     = 2
write(6, "34", 234)                       = 2
write(6, "m", 1m)                        = 1
write(6, "Cargo.toml.bak \342\237\266   Cargo.toml", 31Cargo.toml.bak ⟶   Cargo.toml) = 31
write(6, "\33[0m", 4�[0m)                   = 4
write(6, "\n", 1
)                       = 1
write(6, "\33[", 2�[)                     = 2
write(6, "34", 234)                       = 2
write(6, "m", 1m)                        = 1
write(6, "\342\224\200\342\224\200\342\224\200\342\224\200\342\224\200\342\224\200\342\224\200\342\224\200\342\224\200\342\224\200\342\224"..., 240────────────────────────────────────────────────────────────────────────────────) = 240
write(6, "\33[0m", 4�[0m)                   = 4
write(6, "\n", 1
)                       = 1
mmap(NULL, 675840, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f732e8ac000
openat(AT_FDCWD, "/proc/stat", O_RDONLY|O_CLOEXEC) = 7
read(7, "cpu  143738 231 45028 994317 107"..., 8192) = 3610
close(7)                                = 0
openat(AT_FDCWD, "/proc/stat", O_RDONLY|O_CLOEXEC) = 7
openat(AT_FDCWD, "/proc/cpuinfo", O_RDONLY|O_CLOEXEC) = 8
statx(0, NULL, AT_STATX_SYNC_AS_STAT, STATX_ALL, NULL) = -1 EFAULT (Bad address)
statx(8, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0444, stx_size=0, ...}) = 0
lseek(8, 0, SEEK_CUR)                   = 0
read(8, "processor\t: 0\nvendor_id\t: Genuin", 32) = 32
read(8, "eIntel\ncpu family\t: 6\nmodel\t\t: 1", 32) = 32
read(8, "58\nmodel name\t: Intel(R) Core(TM"..., 64) = 64
read(8, "g\t: 10\nmicrocode\t: 0xea\ncpu MHz\t"..., 128) = 128
read(8, "\t: 0\ninitial apicid\t: 0\nfpu\t\t: y"..., 256) = 256
read(8, " arch_perfmon pebs bts rep_good "..., 512) = 512
read(8, " hwp_notify hwp_act_window hwp_e"..., 1024) = 1024
read(8, "cpuid aperfmperf pni pclmulqdq d"..., 2048) = 2048
read(8, "1gb flexpriority tsc_offset vtpr"..., 4096) = 3289
read(8, "processor\t: 5\nvendor_id\t: Genuin"..., 807) = 807
read(8, "i ssbd ibrs ibpb stibp tpr_shado"..., 8192) = 672
read(8, "", 7520)                       = 0
close(8)                                = 0
read(7, "cpu  143740 231 45028 994325 107"..., 8192) = 3610
openat(AT_FDCWD, "/sys/devices/system/cpu/cpu0/cpufreq/scaling_cur_freq", O_RDONLY|O_CLOEXEC) = 8
statx(8, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0444, stx_size=4096, ...}) = 0
lseek(8, 0, SEEK_CUR)                   = 0
read(8, "3900006\n", 4096)              = 8
read(8, "", 4088)                       = 0
close(8)                                = 0
openat(AT_FDCWD, "/sys/devices/system/cpu/cpu1/cpufreq/scaling_cur_freq", O_RDONLY|O_CLOEXEC) = 8
statx(8, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0444, stx_size=4096, ...}) = 0
lseek(8, 0, SEEK_CUR)                   = 0
read(8, "3900000\n", 4096)              = 8
read(8, "", 4088)                       = 0
close(8)                                = 0
openat(AT_FDCWD, "/sys/devices/system/cpu/cpu2/cpufreq/scaling_cur_freq", O_RDONLY|O_CLOEXEC) = 8
statx(8, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0444, stx_size=4096, ...}) = 0
lseek(8, 0, SEEK_CUR)                   = 0
read(8, "3893884\n", 4096)              = 8
read(8, "", 4088)                       = 0
close(8)                                = 0
openat(AT_FDCWD, "/sys/devices/system/cpu/cpu3/cpufreq/scaling_cur_freq", O_RDONLY|O_CLOEXEC) = 8
statx(8, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0444, stx_size=4096, ...}) = 0
lseek(8, 0, SEEK_CUR)                   = 0
read(8, "3899665\n", 4096)              = 8
read(8, "", 4088)                       = 0
close(8)                                = 0
openat(AT_FDCWD, "/sys/devices/system/cpu/cpu4/cpufreq/scaling_cur_freq", O_RDONLY|O_CLOEXEC) = 8
statx(8, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0444, stx_size=4096, ...}) = 0
lseek(8, 0, SEEK_CUR)                   = 0
read(8, "3899951\n", 4096)              = 8
read(8, "", 4088)                       = 0
close(8)                                = 0
openat(AT_FDCWD, "/sys/devices/system/cpu/cpu5/cpufreq/scaling_cur_freq", O_RDONLY|O_CLOEXEC) = 8
statx(8, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0444, stx_size=4096, ...}) = 0
lseek(8, 0, SEEK_CUR)                   = 0
read(8, "3900023\n", 4096)              = 8
read(8, "", 4088)                       = 0
close(8)                                = 0
close(7)                                = 0
getpid()                                = 100005

dandavison · 2021-12-10T09:58:10Z

Thanks! Hm. If anyone has time to help find what I've done wrong, the next step could be to add print statements to the 3rd party library and alter the entry in Cargo.toml to take the library from local disk.

dandavison · 2021-12-10T10:54:15Z

OK I think there was a mistake in the sysinfo PR that I missed when I reviewed it. I've updated this branch, although at this point we are pointing at a temporary branch of the upstream that isn't passing tests yet :)

unphased · 2021-12-10T16:37:19Z

Hmm I tried pulling and building but

❯ cargo build --release         
    Updating git repository `https://github.com/GuillaumeGomez/sysinfo`
error: failed to get `sysinfo` as a dependency of package `git-delta v0.11.2 (/home/slu/delta)`

Caused by:
  failed to load source for dependency `sysinfo`

Caused by:
  Unable to update https://github.com/GuillaumeGomez/sysinfo?branch=fixes#da26f194

Caused by:
  object not found - no match for id (da26f1944f7a7a5e81edf585be6989feb113b96b); class=Odb (9); code=NotFound (-3)

dandavison · 2021-12-10T18:06:17Z

@unphased that may have been because the delta was pointing at a feature branch in the upstream repo. The sysinfo author is working on this issue and this branch is now pointing at his latest fix.

unphased · 2021-12-10T18:18:33Z

Success:

❯ time diff -u <(echo abc) <(echo bcd) | ~/bin/delta  

/proc/self/fd/15:1:
  1¦   │abc
   ¦  1│bcd
diff -u <(echo abc) <(echo bcd)  0.00s user 0.01s system 96% cpu 0.008 total
~/bin/delta  0.04s user 0.01s system 98% cpu 0.046 total

git diff/log are finally snappy again!

dandavison · 2021-12-11T03:07:28Z

Great, thanks @unphased!

ttys3 · 2021-12-11T05:18:36Z

the old commit hash is gone. now is this one( GuillaumeGomez/sysinfo@67a586c)

  Updating sysinfo v0.21.2 (https://github.com/GuillaumeGomez/sysinfo?branch=update-if-needed#0e5e3e1f) -> #67a586c6

then compiled and tested.

the speed comes back again! Cheers

for (( c=1; c<=10; c++ ))
do
   sleep 1
time ./target/release/delta Cargo.lock Cargo.toml > /dev/null

done
./target/release/delta Cargo.lock Cargo.toml > /dev/null  0.06s user 0.01s system 102% cpu 0.064 total
./target/release/delta Cargo.lock Cargo.toml > /dev/null  0.07s user 0.00s system 45% cpu 0.156 total
./target/release/delta Cargo.lock Cargo.toml > /dev/null  0.05s user 0.02s system 103% cpu 0.064 total
./target/release/delta Cargo.lock Cargo.toml > /dev/null  0.06s user 0.01s system 103% cpu 0.064 total
./target/release/delta Cargo.lock Cargo.toml > /dev/null  0.07s user 0.00s system 102% cpu 0.065 total
./target/release/delta Cargo.lock Cargo.toml > /dev/null  0.05s user 0.01s system 103% cpu 0.064 total
./target/release/delta Cargo.lock Cargo.toml > /dev/null  0.06s user 0.01s system 103% cpu 0.065 total
./target/release/delta Cargo.lock Cargo.toml > /dev/null  0.07s user 0.00s system 102% cpu 0.065 total
./target/release/delta Cargo.lock Cargo.toml > /dev/null  0.05s user 0.01s system 103% cpu 0.064 total
./target/release/delta Cargo.lock Cargo.toml > /dev/null  0.06s user 0.01s system 102% cpu 0.065 total

GuillaumeGomez · 2021-12-11T13:48:00Z

Perfect, thanks for the confirmation. I'll merge the PR then.

Fixes #839 Ref GuillaumeGomez/sysinfo#632

Ref GuillaumeGomez/sysinfo#636

commit d647acfbf216848a8237e1f9251b2c48860a547f Merge: 989ac6c 67a586c Author: Guillaume Gomez <[email protected]> Date: 2 hours ago Merge pull request #636 from GuillaumeGomez/update-if-needed Only update processors if needed

dandavison · 2021-12-11T20:30:57Z

I'm merging this branch now. It currently has a Cargo.toml dependency pointed at an explicit commit SHA on Github rather than a released crates.io package version. Is it a sin to perform a delta release in that state?

Ref #845

dandavison mentioned this pull request Dec 10, 2021

Add possibility to specify what to update in processes GuillaumeGomez/sysinfo#634

Merged

unphased mentioned this pull request Dec 10, 2021

🐛 Takes about a second to execute #844

Closed

dandavison mentioned this pull request Dec 10, 2021

Only update processors if needed GuillaumeGomez/sysinfo#636

Merged

dandavison added 4 commits December 11, 2021 15:15

Do not query CPU data when querying process data

3cf4b59

Fixes #839 Ref GuillaumeGomez/sysinfo#632

Update branch of sysinfo

cd1e9a2

Update upstream sysinfo commit

20b26a2

Ref GuillaumeGomez/sysinfo#636

dandavison force-pushed the sysinfo-processrefreshkind branch from 395a85f to 7be04e5 Compare December 11, 2021 20:16

dandavison changed the base branch from procs to master December 11, 2021 20:16

dandavison merged commit 69c7aaa into master Dec 11, 2021

dandavison deleted the sysinfo-processrefreshkind branch December 11, 2021 20:31

dandavison added a commit that referenced this pull request Dec 11, 2021

Fix specification of git revision in Cargo.toml dependency

8dfd22b

Ref #845

th1000s mentioned this pull request Dec 16, 2021

Option to keep fewer files open when querying processes GuillaumeGomez/sysinfo#646

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Do not query CPU data when querying process data #845

Do not query CPU data when querying process data #845

dandavison commented Dec 10, 2021

unphased commented Dec 10, 2021 •

edited

Loading

dandavison commented Dec 10, 2021

unphased commented Dec 10, 2021

ttys3 commented Dec 10, 2021 •

edited

Loading

ttys3 commented Dec 10, 2021

dandavison commented Dec 10, 2021

dandavison commented Dec 10, 2021

unphased commented Dec 10, 2021

dandavison commented Dec 10, 2021

unphased commented Dec 10, 2021 •

edited

Loading

dandavison commented Dec 11, 2021

ttys3 commented Dec 11, 2021 •

edited

Loading

GuillaumeGomez commented Dec 11, 2021

dandavison commented Dec 11, 2021

Do not query CPU data when querying process data #845

Do not query CPU data when querying process data #845

Conversation

dandavison commented Dec 10, 2021

unphased commented Dec 10, 2021 • edited Loading

dandavison commented Dec 10, 2021

unphased commented Dec 10, 2021

ttys3 commented Dec 10, 2021 • edited Loading

ttys3 commented Dec 10, 2021

dandavison commented Dec 10, 2021

dandavison commented Dec 10, 2021

unphased commented Dec 10, 2021

dandavison commented Dec 10, 2021

unphased commented Dec 10, 2021 • edited Loading

dandavison commented Dec 11, 2021

ttys3 commented Dec 11, 2021 • edited Loading

GuillaumeGomez commented Dec 11, 2021

dandavison commented Dec 11, 2021

unphased commented Dec 10, 2021 •

edited

Loading

ttys3 commented Dec 10, 2021 •

edited

Loading

unphased commented Dec 10, 2021 •

edited

Loading

ttys3 commented Dec 11, 2021 •

edited

Loading