in reply to Re^2: Perl threads loss of performance with system call
in thread Perl threads loss of performance with system call

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 ...

bw, bliako

Replies are listed 'Best First'.
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.