Fluctuating performance and sometimes "The following threads wouldn't die: [gc]"

General
1

In the following we run a test 5 times

$ time swipl -g seeye,halt seeye.pl tests/dpe.pl
re(b,B),re(c,B)

real    0m0.025s
user    0m0.017s
sys     0m0.009s
$ time swipl -g seeye,halt seeye.pl tests/dpe.pl
re(b,B),re(c,B)

real    0m0.028s
user    0m0.027s
sys     0m0.001s
$ time swipl -g seeye,halt seeye.pl tests/dpe.pl
re(b,B),re(c,B)

real    0m0.125s
user    0m0.008s
sys     0m0.017s
$ time swipl -g seeye,halt seeye.pl tests/dpe.pl
re(b,B),re(c,B)
% The following threads wouldn't die: [gc]

real    0m1.029s
user    0m0.008s
sys     0m0.017s
$ time swipl -g seeye,halt seeye.pl tests/dpe.pl
re(b,B),re(c,B)
% The following threads wouldn't die: [gc]

real    0m1.029s
user    0m0.024s
sys     0m0.001s

The code is at http://eulersharp.sourceforge.net/2021/02seeye/seeye.pl and http://eulersharp.sourceforge.net/2021/02seeye/tests/dpe.pl

The times for “real” fluctuate from 0.025s to 1.029s and the larger times
seem to be related with the message “The following threads wouldn’t die: [gc]”.

1 Like
2

The 1 sec is due to the failure to terminate the gc thread as Prolog termination tries to kill all threads gracefully and gives up if this doesn’t work within 1 second. So the question becomes why it can’t successfully kill the gc thread. I don’t think I’ve seen that before. I’ll try to have a look one of these days. A quick work-around is probably to use the --no-threads option.

3

Hi Jan, the difference when using --no-threads is really spectacular:

$ time repeat 20 swipl -g seeye,halt seeye.pl tests/dpe.pl
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
% The following threads wouldn't die: [gc]
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
% The following threads wouldn't die: [gc]
re(b,B),re(c,B)
re(b,B),re(c,B)
% The following threads wouldn't die: [gc]
re(b,B),re(c,B)
% The following threads wouldn't die: [gc]
re(b,B),re(c,B)
re(b,B),re(c,B)
% The following threads wouldn't die: [gc]
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
% The following threads wouldn't die: [gc]
re(b,B),re(c,B)
re(b,B),re(c,B)

real    0m7.555s
user    0m0.409s
sys     0m0.027s


$ time repeat 20 swipl --no-threads -g seeye,halt seeye.pl tests/dpe.pl
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)
re(b,B),re(c,B)

real    0m0.385s
user    0m0.313s
sys     0m0.079s

So about a factor 20 in “real” time.
I’m running this on

$ uname -a
Linux LAPTOP-MSHQL1P6 4.19.104-microsoft-standard #1 SMP Wed Feb 19 06:37:35 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
1 Like
4

That is due to the apparent failure to kill the gc thread. The somewhat longer runtime may be caused by clause or atom GC running while the real work has completed. Without using a thread for GC the main thread will do the GC job. Avoiding the GC thread may gain a bit by skipping a final GC while terminating the process.

Most likely the difference will get less as the time to do the job gets longer and at some point it is likely the threaded version will win (depending on how much GC is involved). As is you seem to be timing mostly startup and shutdown time for Prolog. If you need the speed, turn the Prolog process into a service that keeps running and use network communication, for example using a unix domain socket.

1 Like