Re: Optimising cygwin fork performance

[Brian Inglis <Brian.Inglis@SystematicSw.ab.ca>]

[-- Attachment #1: Type: text/plain, Size: 3621 bytes --]

On 2020-12-16 10:36, Marco Atzeri via Cygwin-apps wrote:
> On 16.12.2020 13:13, Hamish McIntyre-Bhatty via Cygwin-apps wrote:
>> So I know it's been mentioned a lot that fork is slow on Cygwin, but
>> compared to other people's machines, eg when building, it seems way
>> slower for me.
>>
>> First I'd like to know if there's a good way to measure this that anyone
>> has found, because I'm not sure how to measure it. If I print multiple
>> lines with echo in a script, I can see it printing maybe 2-3 a second -
>> it's very slow.
>>
>> I think this might be because I'm using a Virtual Machine with
>> VirtualBox, and QEMU/KVM might be quicker. I'm using Avira Antivurus,
>> with exceptions for the cygwin install folders (C:\cygwin64, C:\cygwin).
>>
>> It might be nice if we could so some comparisons so I can figure out
>> what's wrong.

Running strace on your forking executable should give you accurate numbers in 
the output, with some work to extract the relevant values.

> Same AV here, W10 64bit (no VM), 2 year old Laptop
> 
> model name      : Intel(R) Core(TM) i5-8250U CPU @ 1.60GHz
> 4 cores
> 
> https://github.com/mondalaci/fork-benchmark
> it seems there is a aging effect
> 
> $ ./fork-benchmark.exe 1000
> Forked, executed and destroyed 1000 processes in 39.928576 seconds.
> 
> $ ./fork-benchmark.exe 1000
> Forked, executed and destroyed 1000 processes in 42.701295 seconds.
> 
> $ ./fork-benchmark.exe 1000
> Forked, executed and destroyed 1000 processes in 49.890909 seconds.
> 
> $ ./fork-benchmark.exe 1000
> Forked, executed and destroyed 1000 processes in 61.657031 seconds.

It's all part of your current process tree.
Running cygserver may help this with appropriate process settings:

$ grep -C1 'kern\.srv\..*_.*' /etc/cygserver.conf

# kern.srv.cleanup_threads: No. of cygserver threads used for cleanup tasks.
# Default: 2, Min: 1, Max: 16, command line option -c, --cleanup-threads
#kern.srv.cleanup_threads 2
kern.srv.cleanup_threads 16

# kern.srv.request_threads: No. of cygserver threads used to serve
#                           application requests.
# Default: 10, Min: 1, Max: 310, command line option -r, --request-threads
#kern.srv.request_threads 10
kern.srv.request_threads 310

# kern.srv.process_cache_size: No. of concurrent processes which can be handled
#                              by Cygserver concurrently.
# Default: 62, Min: 1, Max: 310, command line option -p, --process-cache
#kern.srv.process_cache_size 62
kern.srv.process_cache_size 310

$ ./fork-benchmark 1000
Forked, executed and destroyed 1000 processes in 33.397727 seconds.
$ ./fork-benchmark 1000
Forked, executed and destroyed 1000 processes in 34.70389 seconds.
$ ./fork-benchmark 1000
Forked, executed and destroyed 1000 processes in 34.186709 seconds.
$ ./fork-benchmark 1000
Forked, executed and destroyed 1000 processes in 33.65649 seconds.
$ sed -En '/^model name|^cpu MHz/p;/MHz/q' /proc/cpuinfo
model name      : AMD A10-9700 RADEON R7, 10 COMPUTE CORES 4C+6G
cpu MHz         : 3500.000

$ strace -o fork-benchmark.strace ./fork-benchmark 10
$ egrep '^--- Process [0-9]+ (crea|\(pid: [0-9]+\) exi)ted|dwProcessId 
[0-9]+|ExitProcess n 0x' fork-benchmark.strace > fork-benchmark.log
$ awk '/ [0-9]+! pinfo::exit: /{t+=$2};END{print t/10000"ms"}' fork-benchmark.log
34.1855ms

Faster CPUs, faster memory, bigger caches, SSD drive may help.

-- 
Take care. Thanks, Brian Inglis, Calgary, Alberta, Canada

This email may be disturbing to some readers as it contains
too much technical detail. Reader discretion is advised.
[Data in binary units and prefixes, physical quantities in SI.]

[-- Attachment #2: fork-benchmark.log --]
[-- Type: text/plain, Size: 4926 bytes --]

--- Process 9704 created
   65   18385 [main] fork-benchmark 13592 pinfo::thisproc: myself dwProcessId 9704
--- Process 6712 created
   79    7102 [main] fork-benchmark 13593 pinfo::thisproc: myself dwProcessId 6712
--- Process 11804 created
   75    5642 [main] fork-benchmark 13593 pinfo::thisproc: myself dwProcessId 11804
   51   34992 [main] fork-benchmark 13593! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
   41   11124 [main] fork-benchmark 13593 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 11804 (pid: 13593) exited with status 0x0
--- Process 4176 created
   68    6571 [main] fork-benchmark 13594 pinfo::thisproc: myself dwProcessId 4176
--- Process 1924 created
   77    5786 [main] fork-benchmark 13594 pinfo::thisproc: myself dwProcessId 1924
   51   33582 [main] fork-benchmark 13594! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
   40   10465 [main] fork-benchmark 13594 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 1924 (pid: 13594) exited with status 0x0
--- Process 10576 created
   64    6030 [main] fork-benchmark 13595 pinfo::thisproc: myself dwProcessId 10576
--- Process 6932 created
   76    5798 [main] fork-benchmark 13595 pinfo::thisproc: myself dwProcessId 6932
   42   31674 [main] fork-benchmark 13595! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
   41   10602 [main] fork-benchmark 13595 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 6932 (pid: 13595) exited with status 0x0
--- Process 11184 created
   71    8542 [main] fork-benchmark 13596 pinfo::thisproc: myself dwProcessId 11184
--- Process 1544 created
   75    5640 [main] fork-benchmark 13596 pinfo::thisproc: myself dwProcessId 1544
   68   34454 [main] fork-benchmark 13596! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
   53   10774 [main] fork-benchmark 13596 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 1544 (pid: 13596) exited with status 0x0
--- Process 8404 created
   68    7283 [main] fork-benchmark 13597 pinfo::thisproc: myself dwProcessId 8404
--- Process 1908 created
   73    5514 [main] fork-benchmark 13597 pinfo::thisproc: myself dwProcessId 1908
   45   34388 [main] fork-benchmark 13597! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
   53   11023 [main] fork-benchmark 13597 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 1908 (pid: 13597) exited with status 0x0
--- Process 3724 created
  123    6348 [main] fork-benchmark 13598 pinfo::thisproc: myself dwProcessId 3724
--- Process 1280 created
  156    6800 [main] fork-benchmark 13598 pinfo::thisproc: myself dwProcessId 1280
   46   35177 [main] fork-benchmark 13598! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
   50   12248 [main] fork-benchmark 13598 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 1280 (pid: 13598) exited with status 0x0
--- Process 7452 created
   79    6782 [main] fork-benchmark 13599 pinfo::thisproc: myself dwProcessId 7452
--- Process 11212 created
   89    7645 [main] fork-benchmark 13599 pinfo::thisproc: myself dwProcessId 11212
   42   36209 [main] fork-benchmark 13599! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
   41   13435 [main] fork-benchmark 13599 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 11212 (pid: 13599) exited with status 0x0
--- Process 8836 created
   65    7997 [main] fork-benchmark 13600 pinfo::thisproc: myself dwProcessId 8836
--- Process 9160 created
  131    6518 [main] fork-benchmark 13600 pinfo::thisproc: myself dwProcessId 9160
   44   35142 [main] fork-benchmark 13600! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
  318   12253 [main] fork-benchmark 13600 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 9160 (pid: 13600) exited with status 0x0
--- Process 2884 created
   64    7104 [main] fork-benchmark 13601 pinfo::thisproc: myself dwProcessId 2884
--- Process 9388 created
   72    5373 [main] fork-benchmark 13601 pinfo::thisproc: myself dwProcessId 9388
   48   33496 [main] fork-benchmark 13601! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
   63   10481 [main] fork-benchmark 13601 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 9388 (pid: 13601) exited with status 0x0
--- Process 6292 created
   68    7492 [main] fork-benchmark 13602 pinfo::thisproc: myself dwProcessId 6292
--- Process 7344 created
   72    5412 [main] fork-benchmark 13602 pinfo::thisproc: myself dwProcessId 7344
   42   32741 [main] fork-benchmark 13602! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
   41   10880 [main] fork-benchmark 13602 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 7344 (pid: 13602) exited with status 0x0
   39  612762 [main] fork-benchmark 13592 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 9704 (pid: 13592) exited with status 0x0