g10k has a minimum run time of one second

[anarcat]

Hi!

This might seem like a trivial concern, but we fire up a bunch of g10k commands in our test suite, and it's kind of slow! I know that g10k is actually really fast in terms of what it does, but I'm now faced with a hard one-second-per-run limit that I can't get rid of otherwise.

A good reproducer is just calling -help:

> time g10k --help 2>/dev/null

________________________________________________________
Executed in    1.01 secs      fish           external
   usr time    0.64 millis  642.00 micros    0.00 millis
   sys time   11.93 millis  139.00 micros   11.79 millis

That's a whole second doing essentially ... well, nothing: the total user/sys time there is a couple miliseconds at most.

This seems to be a locking issue similar to #230. The way -help looks, it does seem like something is spinning while threads complete. This, of course, also applies to an empty -puppetfile run:

> /bin/time g10k -puppetfile
Synced ./Puppetfile with 0 git repositories and 0 Forge modules in 0.0s with git (0.0s sync, I/O 0.0s) and Forge (0.0s query+download, I/O 0.0s) using 50 resolve and 20 extract workers
0.00user 0.00system 0:01.01elapsed 1%CPU (0avgtext+0avgdata 31288maxresident)k
0inputs+0outputs (0major+1913minor)pagefaults 0swaps

I understand this might not be a priority, but it seems to me there's something off here. -maxworker doesn't help.

[anarcat]

going through a strace, it's pretty clear something is sleeping for at least one second:

> time strace -ff -e nanosleep g10k --puppetfile
strace: Process 1822079 attached
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, strace: Process 1822080 attached
NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, strace: Process 1822081 attached
NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 1822078] --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1822078, si_uid=1000} ---
[pid 1822079] <... nanosleep resumed>NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, strace: Process 1822082 attached
NULL) = 0
[pid 1822081] --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=1822078, si_uid=1000} ---
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, strace: Process 1822083 attached
NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822081] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 1822081] <... nanosleep resumed>NULL) = 0
[pid 1822079] <... nanosleep resumed>NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000},  <unfinished ...>
[pid 1822080] nanosleep({tv_sec=0, tv_nsec=3000},  <unfinished ...>
[pid 1822079] <... nanosleep resumed>NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=40000},  <unfinished ...>
[pid 1822080] <... nanosleep resumed>NULL) = 0
Synced ./Puppetfile with 0 git repositories and 0 Forge modules in 0.0s with git (0.0s sync, I/O 0.0s) and Forge (0.0s query+download, I/O 0.0s) using 50 resolve and 20 extract workers
[pid 1822081] nanosleep({tv_sec=1, tv_nsec=0},  <unfinished ...>
[pid 1822079] <... nanosleep resumed>NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=80000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=160000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=320000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=640000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=1280000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=2560000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=5120000}, NULL) = 0
[pid 1822079] nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0
[pid 1822081] <... nanosleep resumed>0x7fc1ffffee08) = 0
[pid 1822083] +++ exited with 0 +++
[pid 1822082] +++ exited with 0 +++
[pid 1822081] +++ exited with 0 +++
[pid 1822080] +++ exited with 0 +++
[pid 1822079] +++ exited with 0 +++
+++ exited with 0 +++

________________________________________________________
Executed in    1.02 secs      fish           external
   usr time   11.70 millis  670.00 micros   11.03 millis
   sys time   14.81 millis  147.00 micros   14.66 millis

i couldn't find a trace of such a sleep in g10k itself, so, like #230, it could be in a dependency.

[anarcat]

at first, i thought i had fixed this with the above patch (anarcat@a0b2008), but after applying the patch on the debian package and rebuilding, i found that i still had the bug.

as it turns out, this seems to be an issue specific to the debian package build, because if i build g10k with go build, i can't reproduce this issue.

i've filed this as a bug report in debian, see https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1129765.

[anarcat]

i've filed this as a bug report in debian, see https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1129765.

in there, Shengjing Zhu identified the -race flag as being problematic: i was able to reproduce the issue by building g10k with -race and it goes away when it's removed. It looks like the flag was removed from MacOS builds in 8bfbdaa but never from Linux.

It was added in 12f3a90.

In both cases, no explanation was given for the -race flag, so i suspect it could just be removed.

[xorpaul]

Interesting, I need to release a new version anyway, but first I need to clean up quite some things.

I'll skip the -race flag when creating the new release