Re: Perl threads loss of performance with system call

Replies are listed 'Best First'.
Re^2: Perl threads loss of performance with system call by daniel85 (Novice) on Jul 13, 2021 at 15:32 UTC
I tried, same behaviour. So, just to make it clear what "I see", I recorded my screen and made 2 gifs. Here they are: http://daniel85.rf.gd/slow.gif <-- with sleep 0.001 http://daniel85.rf.gd/fast.gif <-- with sleep 1 (or 0.5, is the same)	[reply]
Re^3: Perl threads loss of performance with system call by bliako (Abbot) on Jul 13, 2021 at 17:19 UTC
I think I see the same effect on fedora! But that may be due to terminal's sequential stdout! Here is a script which can help you debug this further, it prints start and stop time of shell system command and which cpu the shell was at the beginning and at the end (or at least that's what I believe as I am not into the Linux scheduler at all). I think it is better to rely on these numbers rather than on the frequency you see "`spawned 10`" on the terminal, something very unreliable! You can process these timings and see for yourself if there is delay from creating to sleeping. I don't see it, e.g. the 1st shell-command is run at 1626196220.813910751 which is, time-wise, near `spawned 3 at 1626196220.81309` I also observe that `spawned 7 at 1626196220.82161` and `start(i=1, tid=7/449711) on cpu 0: 1626196220.828573978` are very near as well. use threads; use strict; use Time::HiRes qw/clock_gettime CLOCK_REALTIME/; # use this to control which CPU you assign this script # (and in my system also the shell system command) #use Sys::CpuAffinity; #my $success = Sys::CpuAffinity::setAffinity($$, [1]); print "starting at ".clock_gettime(CLOCK_REALTIME)."\n"; my @pool; for(1..50){ push @pool, threads->create(\&mysub); } $_->join for (@pool); sub mysub { print "spawned " . threads->tid . " at ".clock_gettime(CLOCK_REALT +IME)."\n"; #for(1..100){ select(undef, undef, undef, 0.001); } #my $x = 0.0001 + rand(0.0015); my $x = 0.001; my $id; for my $i (1..100){ $id = "i=$i, tid=".threads->tid; print ` echo -n "start($id/\$\$) on cpu "\`cat /proc/\$\$/stat \| cut - +d' ' -f39\`": "; date +%s.%N sleep $x echo -n " stop($id/\$\$) on cpu "\`cat /proc/\$\$/stat \| cut - +d' ' -f39\`": "; date +%s.%N `; } print "ended " . threads->tid . " at ".clock_gettime(CLOCK_REALTIM +E)."\n"; } __END__ starting at 1626196220.80981 spawned 1 at 1626196220.81077 spawned 2 at 1626196220.81192 spawned 3 at 1626196220.81309 spawned 4 at 1626196220.81466 spawned 5 at 1626196220.81614 spawned 6 at 1626196220.818 start(i=1, tid=1/449647) on cpu 3: 1626196220.813910751 stop(i=1, tid=1/449647) on cpu 3: 1626196220.818011634 start(i=1, tid=2/449649) on cpu 1: 1626196220.815133617 stop(i=1, tid=2/449649) on cpu 3: 1626196220.819228058 start(i=1, tid=3/449654) on cpu 4: 1626196220.816404247 stop(i=1, tid=3/449654) on cpu 2: 1626196220.820722313 spawned 7 at 1626196220.82161 spawned 8 at 1626196220.8235 start(i=1, tid=4/449665) on cpu 6: 1626196220.818088441 stop(i=1, tid=4/449665) on cpu 4: 1626196220.825072117 spawned 9 at 1626196220.82603 spawned 10 at 1626196220.82844 start(i=1, tid=5/449675) on cpu 4: 1626196220.820177902 start(i=1, tid=6/449684) on cpu 4: 1626196220.824213073 ... [download] bw, bliako	[reply] [d/l] [select]
Re^4: Perl threads loss of performance with system call by daniel85 (Novice) on Jul 13, 2021 at 20:38 UTC
So, just to convince everybody, here is the code with an "echo TEST": spawned 1 at 1626208500.02524 spawned 2 at 1626208500.03125 spawned 3 at 1626208500.0412 spawned 4 at 1626208500.06128 spawned 5 at 1626208500.09415 spawned 6 at 1626208500.15344 spawned 7 at 1626208500.21059 spawned 8 at 1626208500.29763 spawned 9 at 1626208500.41771 spawned 10 at 1626208500.50572 spawned 11 at 1626208500.58165 spawned 12 at 1626208500.65737 spawned 13 at 1626208500.75017 spawned 14 at 1626208500.81693 spawned 15 at 1626208500.92765 spawned 16 at 1626208501.01735 spawned 17 at 1626208501.1014 spawned 18 at 1626208501.20233 spawned 19 at 1626208501.3277 spawned 20 at 1626208501.48578 spawned 21 at 1626208501.60823 spawned 22 at 1626208501.76184 spawned 23 at 1626208501.91074 spawned 24 at 1626208502.05749 spawned 25 at 1626208502.18209 spawned 26 at 1626208502.34025 spawned 27 at 1626208502.50691 spawned 28 at 1626208502.64673 spawned 29 at 1626208502.7651 spawned 30 at 1626208502.85567 spawned 31 at 1626208502.99799 spawned 32 at 1626208503.15354 spawned 33 at 1626208503.25317 spawned 34 at 1626208503.38676 spawned 35 at 1626208503.5169 spawned 36 at 1626208503.65632 spawned 37 at 1626208503.75869 spawned 38 at 1626208503.92774 spawned 39 at 1626208504.03994 spawned 40 at 1626208504.167 spawned 41 at 1626208504.30035 spawned 42 at 1626208504.43802 spawned 43 at 1626208504.55466 spawned 44 at 1626208504.7039 spawned 45 at 1626208504.83908 spawned 46 at 1626208504.99497 spawned 47 at 1626208505.09726 spawned 48 at 1626208505.32359 spawned 49 at 1626208505.37484 spawned 50 at 1626208505.52592 And here is the code executed with a "sleep 1": spawned 1 at 1626208578.42362 spawned 2 at 1626208578.42779 spawned 3 at 1626208578.43176 spawned 4 at 1626208578.43626 spawned 5 at 1626208578.43955 spawned 6 at 1626208578.44196 spawned 7 at 1626208578.44448 spawned 8 at 1626208578.44704 spawned 9 at 1626208578.44959 spawned 10 at 1626208578.45191 spawned 11 at 1626208578.4547 spawned 12 at 1626208578.45769 spawned 13 at 1626208578.46019 spawned 14 at 1626208578.46266 spawned 15 at 1626208578.46511 spawned 16 at 1626208578.46765 spawned 17 at 1626208578.47016 spawned 18 at 1626208578.47294 spawned 19 at 1626208578.476 spawned 20 at 1626208578.47854 spawned 21 at 1626208578.48121 spawned 22 at 1626208578.48381 spawned 23 at 1626208578.48643 spawned 24 at 1626208578.48906 spawned 25 at 1626208578.49219 spawned 26 at 1626208578.49523 spawned 27 at 1626208578.49809 spawned 28 at 1626208578.50102 spawned 29 at 1626208578.50378 spawned 30 at 1626208578.50669 spawned 31 at 1626208578.5094 spawned 32 at 1626208578.51287 spawned 33 at 1626208578.51628 spawned 34 at 1626208578.51923 spawned 35 at 1626208578.52191 spawned 36 at 1626208578.52475 spawned 37 at 1626208578.52748 spawned 38 at 1626208578.53011 spawned 39 at 1626208578.53321 spawned 40 at 1626208578.53636 spawned 41 at 1626208578.53904 spawned 42 at 1626208578.54178 spawned 43 at 1626208578.54451 spawned 44 at 1626208578.54737 spawned 45 at 1626208578.55008 spawned 46 at 1626208578.55334 spawned 47 at 1626208578.55657 spawned 48 at 1626208578.55934 spawned 49 at 1626208578.56212 spawned 50 at 1626208578.56489 Btw, I see the same on my work server, 50 cores, running Fedora Core 30, perl v5.28.2, and on my MacBook, perl v5.28.2.	[reply]
Re^3: Perl threads loss of performance with system call by karlgoethebier (Abbot) on Jul 13, 2021 at 17:05 UTC
Thanks. But i don't believe so much in animated gifs but in Benchmark. And in the recording i see your code and not mine. And probably we should better forget this strange loop with sleep and echo and talk about your real command. And BTW, from my sleep manpage: "The sleep command will accept and honor a non-integer number of specified seconds (with a `.' character as a decimal point). This is a non-portable extension, and its use will nearly guarantee that a shell script will not execute properly on another system." Holy Joe! Best regards, Karl ŤThe Crux of the Biscuit is the Apostropheť	[reply]