runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: runsolver -s SIGUSR1 -M 1124 -C 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/p2cudf-basic-1.15/paranoid-size/real/bccf69ae-db9e-11df-9a24-00163e3d3b7c.cudf.log.runsolver /home/competition/p2cudf-basic-1.15/p2cudf-basic-1.15 /home/competition/data/real/bccf69ae-db9e-11df-9a24-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/p2cudf-basic-1.15/paranoid-size/real/bccf69ae-db9e-11df-9a24-00163e3d3b7c.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.05 1.08 1.00 2/65 4622
/proc/meminfo: memFree=661488/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=3152 CPUtime=0
/proc/4622/stat : 4622 (runsolver) R 4621 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115472197 3227648 32 18446744073709551615 134512640 134586868 4294410672 4294408720 4151354416 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 788 32 0 19 0 73 0

[startup+0.145093 s]
/proc/loadavg: 1.05 1.08 1.00 2/65 4622
/proc/meminfo: memFree=661488/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 9172

[startup+0.200247 s]
/proc/loadavg: 1.05 1.08 1.00 2/65 4622
/proc/meminfo: memFree=661488/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 9172

[startup+0.300268 s]
/proc/loadavg: 1.05 1.08 1.00 2/65 4622
/proc/meminfo: memFree=661488/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 9172

[startup+0.700212 s]
/proc/loadavg: 1.05 1.08 1.00 2/65 4622
/proc/meminfo: memFree=661488/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 9172

[startup+1.50062 s]
/proc/loadavg: 1.05 1.08 1.00 4/76 4634
/proc/meminfo: memFree=552644/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
[pid=4625] ppid=4622 vsize=1061576 CPUtime=1.4
/proc/4625/stat : 4625 (java) S 4622 4622 1745 0 -1 4202496 39864 0 0 0 126 14 0 0 20 0 10 0 115472198 1087053824 36526 18446744073709551615 4194304 4228012 140736395924560 140736395915584 140592800591477 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/4625/statm: 265394 36526 2349 9 0 252744 0
[pid=4625/tid=4626] ppid=4622 vsize=1061576 CPUtime=0.59
/proc/4625/task/4626/stat : 4626 (java) R 4622 4622 1745 0 -1 4202560 19703 0 0 0 51 8 0 0 20 0 10 0 115472199 1087053824 36526 18446744073709551615 4194304 4228012 140736395924560 140592807117504 140592705055061 0 4 0 16800975 0 0 0 -1 0 0 0 9 0 0
[pid=4625/tid=4627] ppid=4622 vsize=1061576 CPUtime=0
/proc/4625/task/4627/stat : 4627 (java) S 4622 4622 1745 0 -1 4202560 3 0 0 0 0 0 0 0 20 0 10 0 115472200 1087053824 36526 18446744073709551615 4194304 4228012 140736395924560 140592699763840 140592800605771 0 0 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4628] ppid=4622 vsize=1061576 CPUtime=0
/proc/4625/task/4628/stat : 4628 (java) S 4622 4622 1745 0 -1 4202560 15 0 0 0 0 0 0 0 20 0 10 0 115472201 1087053824 36526 18446744073709551615 4194304 4228012 140736395924560 140592698710032 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4629] ppid=4622 vsize=1061576 CPUtime=0
/proc/4625/task/4629/stat : 4629 (java) S 4622 4622 1745 0 -1 4202560 6 0 0 0 0 0 0 0 20 0 10 0 115472201 1087053824 36526 18446744073709551615 4194304 4228012 140736395924560 140592697657248 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4630] ppid=4622 vsize=1061576 CPUtime=0
/proc/4625/task/4630/stat : 4630 (java) S 4622 4622 1745 0 -1 4202560 1 0 0 0 0 0 0 0 20 0 10 0 115472204 1087053824 36526 18446744073709551615 4194304 4228012 140736395924560 140592696605680 140592800613408 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4631] ppid=4622 vsize=1061576 CPUtime=0.39
/proc/4625/task/4631/stat : 4631 (java) R 4622 4622 1745 0 -1 4202560 9511 0 0 0 37 2 0 0 20 0 10 0 115472204 1087053824 36526 18446744073709551615 4194304 4228012 140736395924560 140592695552784 140592787105957 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4632] ppid=4622 vsize=1061576 CPUtime=0.39
/proc/4625/task/4632/stat : 4632 (java) R 4622 4622 1745 0 -1 4202560 9358 0 0 0 37 2 0 0 20 0 10 0 115472204 1087053824 36526 18446744073709551615 4194304 4228012 140736395924560 140592694488088 140592782206480 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4633] ppid=4622 vsize=1061576 CPUtime=0
/proc/4625/task/4633/stat : 4633 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 10 0 115472204 1087053824 36526 18446744073709551615 4194304 4228012 140736395924560 140592693447888 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4634] ppid=4622 vsize=1061576 CPUtime=0
/proc/4625/task/4634/stat : 4634 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 10 0 115472204 1087053824 36526 18446744073709551615 4194304 4228012 140736395924560 140592692395392 140592800605771 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.4
Current children cumulated vsize (KiB) 1070748

[startup+3.10067 s]
/proc/loadavg: 1.20 1.11 1.01 2/76 4634
/proc/meminfo: memFree=377432/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
[pid=4625] ppid=4622 vsize=1061104 CPUtime=2.8
/proc/4625/stat : 4625 (java) S 4622 4622 1745 0 -1 4202496 89602 0 0 0 250 30 0 0 20 0 10 0 115472198 1086570496 85566 18446744073709551615 4194304 4228012 140736395924560 140736395915584 140592800591477 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/4625/statm: 265276 85566 2370 9 0 252626 0
[pid=4625/tid=4626] ppid=4622 vsize=1061104 CPUtime=1.44
/proc/4625/task/4626/stat : 4626 (java) D 4622 4622 1745 0 -1 4202560 47411 0 0 0 128 16 0 0 20 0 10 0 115472199 1086570496 85566 18446744073709551615 4194304 4228012 140736395924560 140592807117504 140592800616845 0 4 0 16800975 0 0 0 -1 0 0 0 27 0 0
[pid=4625/tid=4627] ppid=4622 vsize=1061104 CPUtime=0.37
/proc/4625/task/4627/stat : 4627 (java) S 4622 4622 1745 0 -1 4202560 21942 0 0 0 29 8 0 0 20 0 10 0 115472200 1086570496 85566 18446744073709551615 4194304 4228012 140736395924560 140592699763840 140592800605771 0 0 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4628] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4628/stat : 4628 (java) S 4622 4622 1745 0 -1 4202560 16 0 0 0 0 0 0 0 20 0 10 0 115472201 1086570496 85566 18446744073709551615 4194304 4228012 140736395924560 140592698710032 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4629] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4629/stat : 4629 (java) S 4622 4622 1745 0 -1 4202560 9 0 0 0 0 0 0 0 20 0 10 0 115472201 1086570496 85566 18446744073709551615 4194304 4228012 140736395924560 140592697657248 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4630] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4630/stat : 4630 (java) S 4622 4622 1745 0 -1 4202560 1 0 0 0 0 0 0 0 20 0 10 0 115472204 1086570496 85566 18446744073709551615 4194304 4228012 140736395924560 140592696605680 140592800613408 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4631] ppid=4622 vsize=1061104 CPUtime=0.48
/proc/4625/task/4631/stat : 4631 (java) S 4622 4622 1745 0 -1 4202560 9521 0 0 0 46 2 0 0 20 0 10 0 115472204 1086570496 85566 18446744073709551615 4194304 4228012 140736395924560 140592695553040 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4632] ppid=4622 vsize=1061104 CPUtime=0.46
/proc/4625/task/4632/stat : 4632 (java) S 4622 4622 1745 0 -1 4202560 9435 0 0 0 44 2 0 0 20 0 10 0 115472204 1086570496 85566 18446744073709551615 4194304 4228012 140736395924560 140592694500368 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4633] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4633/stat : 4633 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 10 0 115472204 1086570496 85566 18446744073709551615 4194304 4228012 140736395924560 140592693447888 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4634] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4634/stat : 4634 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 10 0 115472204 1086570496 85566 18446744073709551615 4194304 4228012 140736395924560 140592692395392 140592800605771 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 1070276

[startup+6.30078 s]
/proc/loadavg: 1.20 1.11 1.01 4/76 4634
/proc/meminfo: memFree=277612/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
[pid=4625] ppid=4622 vsize=1061104 CPUtime=5.81
/proc/4625/stat : 4625 (java) S 4622 4622 1745 0 -1 4202496 98935 0 0 0 546 35 0 0 20 0 10 0 115472198 1086570496 94710 18446744073709551615 4194304 4228012 140736395924560 140736395915584 140592800591477 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/4625/statm: 265276 94710 2375 9 0 252626 0
[pid=4625/tid=4626] ppid=4622 vsize=1061104 CPUtime=2.66
/proc/4625/task/4626/stat : 4626 (java) R 4622 4622 1745 0 -1 4202560 47711 0 0 0 248 18 0 0 20 0 10 0 115472199 1086570496 94710 18446744073709551615 4194304 4228012 140736395924560 140592807124920 140592704546910 0 4 0 16800975 0 0 0 -1 0 0 0 42 0 0
[pid=4625/tid=4627] ppid=4622 vsize=1061104 CPUtime=0.54
/proc/4625/task/4627/stat : 4627 (java) S 4622 4622 1745 0 -1 4202560 30208 0 0 0 43 11 0 0 20 0 10 0 115472200 1086570496 94710 18446744073709551615 4194304 4228012 140736395924560 140592699763840 140592800605771 0 0 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4628] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4628/stat : 4628 (java) S 4622 4622 1745 0 -1 4202560 16 0 0 0 0 0 0 0 20 0 10 0 115472201 1086570496 94710 18446744073709551615 4194304 4228012 140736395924560 140592698710032 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4629] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4629/stat : 4629 (java) S 4622 4622 1745 0 -1 4202560 9 0 0 0 0 0 0 0 20 0 10 0 115472201 1086570496 94710 18446744073709551615 4194304 4228012 140736395924560 140592697657248 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4630] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4630/stat : 4630 (java) S 4622 4622 1745 0 -1 4202560 1 0 0 0 0 0 0 0 20 0 10 0 115472204 1086570496 94710 18446744073709551615 4194304 4228012 140736395924560 140592696605680 140592800613408 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4631] ppid=4622 vsize=1061104 CPUtime=1.33
/proc/4625/task/4631/stat : 4631 (java) R 4622 4622 1745 0 -1 4202560 9890 0 0 0 131 2 0 0 20 0 10 0 115472204 1086570496 94710 18446744073709551615 4194304 4228012 140736395924560 140592695539128 140592784895968 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4632] ppid=4622 vsize=1061104 CPUtime=1.25
/proc/4625/task/4632/stat : 4632 (java) R 4622 4622 1745 0 -1 4202560 9833 0 0 0 122 3 0 0 20 0 10 0 115472204 1086570496 94710 18446744073709551615 4194304 4228012 140736395924560 140592694500112 140592784871273 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4633] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4633/stat : 4633 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 10 0 115472204 1086570496 94710 18446744073709551615 4194304 4228012 140736395924560 140592693447888 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4634] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4634/stat : 4634 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 10 0 115472204 1086570496 94710 18446744073709551615 4194304 4228012 140736395924560 140592692395392 140592800605771 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 5.81
Current children cumulated vsize (KiB) 1070276

Solver just ended. Dumping a history of the last processes samples

[startup+6.40099 s]
/proc/loadavg: 1.20 1.11 1.01 4/76 4634
/proc/meminfo: memFree=277612/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
[pid=4625] ppid=4622 vsize=1061104 CPUtime=5.91
/proc/4625/stat : 4625 (java) S 4622 4622 1745 0 -1 4202496 98946 0 0 0 556 35 0 0 20 0 10 0 115472198 1086570496 94721 18446744073709551615 4194304 4228012 140736395924560 140736395915584 140592800591477 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/4625/statm: 265276 94721 2375 9 0 252626 0
[pid=4625/tid=4626] ppid=4622 vsize=1061104 CPUtime=2.7
/proc/4625/task/4626/stat : 4626 (java) R 4622 4622 1745 0 -1 4202560 47721 0 0 0 252 18 0 0 20 0 10 0 115472199 1086570496 94721 18446744073709551615 4194304 4228012 140736395924560 140592807126256 140592704638871 0 4 0 16800975 0 0 0 -1 0 0 0 42 0 0
[pid=4625/tid=4627] ppid=4622 vsize=1061104 CPUtime=0.54
/proc/4625/task/4627/stat : 4627 (java) S 4622 4622 1745 0 -1 4202560 30208 0 0 0 43 11 0 0 20 0 10 0 115472200 1086570496 94721 18446744073709551615 4194304 4228012 140736395924560 140592699763840 140592800605771 0 0 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4628] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4628/stat : 4628 (java) S 4622 4622 1745 0 -1 4202560 16 0 0 0 0 0 0 0 20 0 10 0 115472201 1086570496 94721 18446744073709551615 4194304 4228012 140736395924560 140592698710032 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4629] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4629/stat : 4629 (java) S 4622 4622 1745 0 -1 4202560 9 0 0 0 0 0 0 0 20 0 10 0 115472201 1086570496 94721 18446744073709551615 4194304 4228012 140736395924560 140592697657248 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4630] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4630/stat : 4630 (java) S 4622 4622 1745 0 -1 4202560 1 0 0 0 0 0 0 0 20 0 10 0 115472204 1086570496 94721 18446744073709551615 4194304 4228012 140736395924560 140592696605680 140592800613408 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4631] ppid=4622 vsize=1061104 CPUtime=1.36
/proc/4625/task/4631/stat : 4631 (java) R 4622 4622 1745 0 -1 4202560 9890 0 0 0 134 2 0 0 20 0 10 0 115472204 1086570496 94721 18446744073709551615 4194304 4228012 140736395924560 140592695539128 140592782057184 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4632] ppid=4622 vsize=1061104 CPUtime=1.29
/proc/4625/task/4632/stat : 4632 (java) R 4622 4622 1745 0 -1 4202560 9834 0 0 0 126 3 0 0 20 0 10 0 115472204 1086570496 94721 18446744073709551615 4194304 4228012 140736395924560 140592694500112 140592783390896 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4633] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4633/stat : 4633 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 10 0 115472204 1086570496 94721 18446744073709551615 4194304 4228012 140736395924560 140592693447888 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4634] ppid=4622 vsize=1061104 CPUtime=0
/proc/4625/task/4634/stat : 4634 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 10 0 115472204 1086570496 94721 18446744073709551615 4194304 4228012 140736395924560 140592692395392 140592800605771 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 5.91
Current children cumulated vsize (KiB) 1070276

[startup+7.20077 s]
/proc/loadavg: 1.35 1.14 1.02 3/76 4634
/proc/meminfo: memFree=276992/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
[pid=4625] ppid=4622 vsize=1062132 CPUtime=6.69
/proc/4625/stat : 4625 (java) S 4622 4622 1745 0 -1 4202496 99072 0 0 0 634 35 0 0 20 0 11 0 115472198 1087623168 94847 18446744073709551615 4194304 4228012 140736395924560 140736395915584 140592800591477 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/4625/statm: 265533 94847 2378 9 0 252883 0
[pid=4625/tid=4626] ppid=4622 vsize=1062132 CPUtime=3.04
/proc/4625/task/4626/stat : 4626 (java) R 4622 4622 1745 0 -1 4202560 47795 0 0 0 286 18 0 0 20 0 11 0 115472199 1087623168 94847 18446744073709551615 4194304 4228012 140736395924560 140592807116704 140592704638349 0 4 0 16800975 0 0 0 -1 0 0 0 44 0 0
[pid=4625/tid=4627] ppid=4622 vsize=1062132 CPUtime=0.55
/proc/4625/task/4627/stat : 4627 (java) S 4622 4622 1745 0 -1 4202560 30209 0 0 0 44 11 0 0 20 0 11 0 115472200 1087623168 94847 18446744073709551615 4194304 4228012 140736395924560 140592699763840 140592800605771 0 0 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4628] ppid=4622 vsize=1062132 CPUtime=0
/proc/4625/task/4628/stat : 4628 (java) S 4622 4622 1745 0 -1 4202560 16 0 0 0 0 0 0 0 20 0 11 0 115472201 1087623168 94847 18446744073709551615 4194304 4228012 140736395924560 140592698710032 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4629] ppid=4622 vsize=1062132 CPUtime=0
/proc/4625/task/4629/stat : 4629 (java) S 4622 4622 1745 0 -1 4202560 9 0 0 0 0 0 0 0 20 0 11 0 115472201 1087623168 94847 18446744073709551615 4194304 4228012 140736395924560 140592697657248 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4630] ppid=4622 vsize=1062132 CPUtime=0
/proc/4625/task/4630/stat : 4630 (java) S 4622 4622 1745 0 -1 4202560 1 0 0 0 0 0 0 0 20 0 11 0 115472204 1087623168 94847 18446744073709551615 4194304 4228012 140736395924560 140592696605680 140592800613408 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4631] ppid=4622 vsize=1062132 CPUtime=1.58
/proc/4625/task/4631/stat : 4631 (java) R 4622 4622 1745 0 -1 4202560 9925 0 0 0 156 2 0 0 20 0 11 0 115472204 1087623168 94847 18446744073709551615 4194304 4228012 140736395924560 140592695552784 140592786922371 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4632] ppid=4622 vsize=1062132 CPUtime=1.5
/proc/4625/task/4632/stat : 4632 (java) R 4622 4622 1745 0 -1 4202560 9844 0 0 0 147 3 0 0 20 0 11 0 115472204 1087623168 94847 18446744073709551615 4194304 4228012 140736395924560 140592694500112 140592787292246 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4633] ppid=4622 vsize=1062132 CPUtime=0
/proc/4625/task/4633/stat : 4633 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 11 0 115472204 1087623168 94847 18446744073709551615 4194304 4228012 140736395924560 140592693447888 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4634] ppid=4622 vsize=1062132 CPUtime=0
/proc/4625/task/4634/stat : 4634 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 11 0 115472204 1087623168 94847 18446744073709551615 4194304 4228012 140736395924560 140592692395392 140592800605771 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.69
Current children cumulated vsize (KiB) 1071304

[startup+7.60069 s]
/proc/loadavg: 1.35 1.14 1.02 3/76 4634
/proc/meminfo: memFree=276992/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
[pid=4625] ppid=4622 vsize=1063160 CPUtime=6.87
/proc/4625/stat : 4625 (java) S 4622 4622 1745 0 -1 4202496 99090 0 0 0 651 36 0 0 20 0 11 0 115472198 1088675840 94863 18446744073709551615 4194304 4228012 140736395924560 140736395915584 140592800591477 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/4625/statm: 265790 94863 2379 9 0 253140 0
[pid=4625/tid=4626] ppid=4622 vsize=1063160 CPUtime=3.09
/proc/4625/task/4626/stat : 4626 (java) S 4622 4622 1745 0 -1 4202560 47804 0 0 0 291 18 0 0 20 0 11 0 115472199 1088675840 94863 18446744073709551615 4194304 4228012 140736395924560 140592807125936 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 44 0 0
[pid=4625/tid=4627] ppid=4622 vsize=1063160 CPUtime=0.55
/proc/4625/task/4627/stat : 4627 (java) S 4622 4622 1745 0 -1 4202560 30209 0 0 0 44 11 0 0 20 0 11 0 115472200 1088675840 94863 18446744073709551615 4194304 4228012 140736395924560 140592699763840 140592800605771 0 0 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4628] ppid=4622 vsize=1063160 CPUtime=0
/proc/4625/task/4628/stat : 4628 (java) S 4622 4622 1745 0 -1 4202560 16 0 0 0 0 0 0 0 20 0 11 0 115472201 1088675840 94863 18446744073709551615 4194304 4228012 140736395924560 140592698710032 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4629] ppid=4622 vsize=1063160 CPUtime=0
/proc/4625/task/4629/stat : 4629 (java) S 4622 4622 1745 0 -1 4202560 9 0 0 0 0 0 0 0 20 0 11 0 115472201 1088675840 94863 18446744073709551615 4194304 4228012 140736395924560 140592697657248 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4630] ppid=4622 vsize=1063160 CPUtime=0
/proc/4625/task/4630/stat : 4630 (java) S 4622 4622 1745 0 -1 4202560 1 0 0 0 0 0 0 0 20 0 11 0 115472204 1088675840 94863 18446744073709551615 4194304 4228012 140736395924560 140592696605680 140592800613408 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4631] ppid=4622 vsize=1063160 CPUtime=1.63
/proc/4625/task/4631/stat : 4631 (java) S 4622 4622 1745 0 -1 4202560 9927 0 0 0 161 2 0 0 20 0 11 0 115472204 1088675840 94863 18446744073709551615 4194304 4228012 140736395924560 140592695553040 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4632] ppid=4622 vsize=1063160 CPUtime=1.56
/proc/4625/task/4632/stat : 4632 (java) S 4622 4622 1745 0 -1 4202560 9845 0 0 0 153 3 0 0 20 0 11 0 115472204 1088675840 94863 18446744073709551615 4194304 4228012 140736395924560 140592694500368 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4633] ppid=4622 vsize=1063160 CPUtime=0
/proc/4625/task/4633/stat : 4633 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 11 0 115472204 1088675840 94863 18446744073709551615 4194304 4228012 140736395924560 140592693447888 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4634] ppid=4622 vsize=1063160 CPUtime=0
/proc/4625/task/4634/stat : 4634 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 11 0 115472204 1088675840 94863 18446744073709551615 4194304 4228012 140736395924560 140592692395392 140592800605771 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.87
Current children cumulated vsize (KiB) 1072332

[startup+8.00062 s]
/proc/loadavg: 1.35 1.14 1.02 1/77 4636
/proc/meminfo: memFree=276612/1022884 swapFree=0/0
[pid=4622] ppid=4621 vsize=9172 CPUtime=0
/proc/4622/stat : 4622 (p2cudf-basic-1.) S 4621 4622 1745 0 -1 4202496 458 293 0 0 0 0 0 0 20 0 1 0 115472197 9392128 331 18446744073709551615 4194304 5129932 140733262205440 140733262203584 140354226697310 0 65536 16781316 65538 0 0 0 17 0 0 0 0 0 0
/proc/4622/statm: 2293 331 280 229 0 53 0
[pid=4625] ppid=4622 vsize=1063160 CPUtime=7.01
/proc/4625/stat : 4625 (java) S 4622 4622 1745 0 -1 4202496 99094 0 0 0 663 38 0 0 20 0 11 0 115472198 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140736395915584 140592800591477 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/4625/statm: 265790 94867 2379 9 0 253140 0
[pid=4625/tid=4626] ppid=4622 vsize=1063160 CPUtime=3.09
/proc/4625/task/4626/stat : 4626 (java) S 4622 4622 1745 0 -1 4202560 47804 0 0 0 291 18 0 0 20 0 11 0 115472199 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140592807125936 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 44 0 0
[pid=4625/tid=4627] ppid=4622 vsize=1063160 CPUtime=0.55
/proc/4625/task/4627/stat : 4627 (java) S 4622 4622 1745 0 -1 4202560 30209 0 0 0 44 11 0 0 20 0 11 0 115472200 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140592699763840 140592800605771 0 0 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4628] ppid=4622 vsize=1063160 CPUtime=0
/proc/4625/task/4628/stat : 4628 (java) S 4622 4622 1745 0 -1 4202560 16 0 0 0 0 0 0 0 20 0 11 0 115472201 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140592698710032 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4629] ppid=4622 vsize=1063160 CPUtime=0
/proc/4625/task/4629/stat : 4629 (java) S 4622 4622 1745 0 -1 4202560 9 0 0 0 0 0 0 0 20 0 11 0 115472201 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140592697657248 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4630] ppid=4622 vsize=1063160 CPUtime=0
/proc/4625/task/4630/stat : 4630 (java) S 4622 4622 1745 0 -1 4202560 1 0 0 0 0 0 0 0 20 0 11 0 115472204 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140592696605680 140592800613408 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4631] ppid=4622 vsize=1063160 CPUtime=1.66
/proc/4625/task/4631/stat : 4631 (java) D 4622 4622 1745 0 -1 4202560 9927 0 0 0 164 2 0 0 20 0 11 0 115472204 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140592695552784 140592784375839 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4632] ppid=4622 vsize=1063160 CPUtime=1.57
/proc/4625/task/4632/stat : 4632 (java) D 4622 4622 1745 0 -1 4202560 9845 0 0 0 154 3 0 0 20 0 11 0 115472204 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140592694500112 140592784375839 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4633] ppid=4622 vsize=1063160 CPUtime=0
/proc/4625/task/4633/stat : 4633 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 11 0 115472204 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140592693447888 140592800604884 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4634] ppid=4622 vsize=1063160 CPUtime=0
/proc/4625/task/4634/stat : 4634 (java) S 4622 4622 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 11 0 115472204 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140592692395392 140592800605771 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
[pid=4625/tid=4636] ppid=4622 vsize=1063160 CPUtime=0.1
/proc/4625/task/4636/stat : 4636 (java) R 4622 4622 1745 0 -1 4202560 10 0 0 0 7 3 0 0 20 0 11 0 115472932 1088675840 94867 18446744073709551615 4194304 4228012 140736395924560 140592690140400 140592800616749 0 4 0 16800975 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.01
Current children cumulated vsize (KiB) 1072332

Child status: 0
Real time (s): 8.09782
CPU time (s): 7.11244
CPU user time (s): 6.68842
CPU system time (s): 0.424026
CPU usage (%): 87.8316
Max. virtual memory (cumulated for all children) (KiB): 1072332

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.68842
system time used= 0.424026
maximum resident set size= 379524
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 99873
page faults= 1
swaps= 0
block input operations= 27280
block output operations= 288
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 775
involuntary context switches= 2209

runsolver used 0.004 second user time and 0.084005 second system time

The end