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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201108291842/gj-user-solver-1.0/rand796.cudf.user-upgrades.log.runsolver ./gj-user-solver-1.0 /home/misc2010/data/2011/user-upgrades/rand796.cudf /home/misc2010/tmp/201108291842/gj-user-solver-1.0/rand796.cudf.user-upgrades.result -notuptodate,-removed,-changed 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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.32 1.22 1.19 4/35 25555
/proc/meminfo: memFree=298720/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=1984 CPUtime=0
/proc/25555/stat : 25555 (java) R 25554 25554 17511 34816 17511 4202496 387 0 0 0 0 0 0 0 25 0 1 0 46357695 2031616 129 1283457024 134512640 134550932 4287154656 18446744073709551615 4158620720 0 0 0 0 0 0 0 17 0 0 0 0
/proc/25555/statm: 496 129 102 10 0 97 0

[startup+0.164093 s]
/proc/loadavg: 1.32 1.22 1.19 4/35 25555
/proc/meminfo: memFree=298720/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=409920 CPUtime=0.16
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 3986 0 1 0 15 1 0 0 25 0 9 0 46357695 419758080 3414 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102480 3414 1917 10 0 96628 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 412492

[startup+0.204092 s]
/proc/loadavg: 1.32 1.22 1.19 4/35 25555
/proc/meminfo: memFree=298720/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=409920 CPUtime=0.2
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 4074 0 1 0 19 1 0 0 25 0 9 0 46357695 419758080 3502 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102480 3502 1917 10 0 96628 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 412492

[startup+0.304113 s]
/proc/loadavg: 1.32 1.22 1.19 4/35 25555
/proc/meminfo: memFree=298720/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=410472 CPUtime=0.3
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 4449 0 1 0 29 1 0 0 25 0 9 0 46357695 420323328 3877 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102618 3877 1944 10 0 96766 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 413044

[startup+0.704207 s]
/proc/loadavg: 1.32 1.22 1.19 4/35 25555
/proc/meminfo: memFree=298720/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=410612 CPUtime=0.7
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 11975 0 1 0 65 5 0 0 25 0 9 0 46357695 420466688 11216 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102653 11216 2901 10 0 96801 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 413184

[startup+1.50441 s]
/proc/loadavg: 1.32 1.22 1.19 2/44 25564
/proc/meminfo: memFree=240480/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=410744 CPUtime=1.5
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 27419 0 1 0 139 11 0 0 25 0 9 0 46357695 420601856 26660 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102686 26660 2901 10 0 96834 0
[pid=25555/tid=25557] ppid=25554 vsize=410744 CPUtime=0.82
/proc/25555/task/25557/stat : 25557 (java) R 25554 25554 17511 34816 17511 4202560 6709 0 1 0 77 5 0 0 25 0 9 0 46357696 420601856 26660 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=25555/tid=25558] ppid=25554 vsize=410744 CPUtime=0.63
/proc/25555/task/25558/stat : 25558 (java) R 25554 25554 17511 34816 17511 4202560 19322 0 0 0 58 5 0 0 18 0 9 0 46357696 420601856 26660 1283457024 134512640 134550932 4287154656 18446744073709551615 4149266528 0 0 0 16800975 0 0 0 -1 0 0 0 0
[pid=25555/tid=25559] ppid=25554 vsize=410744 CPUtime=0
/proc/25555/task/25559/stat : 25559 (java) S 25554 25554 17511 34816 17511 4202560 15 0 0 0 0 0 0 0 20 0 9 0 46357696 420601856 26660 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25560] ppid=25554 vsize=410744 CPUtime=0
/proc/25555/task/25560/stat : 25560 (java) S 25554 25554 17511 34816 17511 4202560 5 0 0 0 0 0 0 0 20 0 9 0 46357696 420601856 26660 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25561] ppid=25554 vsize=410744 CPUtime=0
/proc/25555/task/25561/stat : 25561 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 9 0 46357698 420601856 26660 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25562] ppid=25554 vsize=410744 CPUtime=0.04
/proc/25555/task/25562/stat : 25562 (java) S 25554 25554 17511 34816 17511 4202560 447 0 0 0 4 0 0 0 16 0 9 0 46357698 420601856 26660 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25563] ppid=25554 vsize=410744 CPUtime=0
/proc/25555/task/25563/stat : 25563 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 9 0 46357698 420601856 26660 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25564] ppid=25554 vsize=410744 CPUtime=0
/proc/25555/task/25564/stat : 25564 (java) S 25554 25554 17511 34816 17511 4202560 2 0 0 0 0 0 0 0 15 0 9 0 46357698 420601856 26660 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 413316

[startup+3.10468 s]
/proc/loadavg: 1.37 1.24 1.19 2/44 25564
/proc/meminfo: memFree=168684/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=410876 CPUtime=3.1
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 51021 0 1 0 292 18 0 0 25 0 9 0 46357695 420737024 50262 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102719 50262 2901 10 0 96867 0
[pid=25555/tid=25557] ppid=25554 vsize=410876 CPUtime=1.42
/proc/25555/task/25557/stat : 25557 (java) R 25554 25554 17511 34816 17511 4202560 13862 0 1 0 136 6 0 0 25 0 9 0 46357696 420737024 50262 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=25555/tid=25558] ppid=25554 vsize=410876 CPUtime=1.62
/proc/25555/task/25558/stat : 25558 (java) R 25554 25554 17511 34816 17511 4202560 35768 0 0 0 152 10 0 0 16 0 9 0 46357696 420737024 50262 1283457024 134512640 134550932 4287154656 18446744073709551615 4150618040 0 0 0 16800975 0 0 0 -1 0 0 0 0
[pid=25555/tid=25559] ppid=25554 vsize=410876 CPUtime=0
/proc/25555/task/25559/stat : 25559 (java) S 25554 25554 17511 34816 17511 4202560 15 0 0 0 0 0 0 0 20 0 9 0 46357696 420737024 50262 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25560] ppid=25554 vsize=410876 CPUtime=0
/proc/25555/task/25560/stat : 25560 (java) S 25554 25554 17511 34816 17511 4202560 5 0 0 0 0 0 0 0 20 0 9 0 46357696 420737024 50262 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25561] ppid=25554 vsize=410876 CPUtime=0
/proc/25555/task/25561/stat : 25561 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 9 0 46357698 420737024 50262 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25562] ppid=25554 vsize=410876 CPUtime=0.04
/proc/25555/task/25562/stat : 25562 (java) S 25554 25554 17511 34816 17511 4202560 450 0 0 0 4 0 0 0 15 0 9 0 46357698 420737024 50262 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25563] ppid=25554 vsize=410876 CPUtime=0
/proc/25555/task/25563/stat : 25563 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 9 0 46357698 420737024 50262 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25564] ppid=25554 vsize=410876 CPUtime=0
/proc/25555/task/25564/stat : 25564 (java) S 25554 25554 17511 34816 17511 4202560 2 0 0 0 0 0 0 0 15 0 9 0 46357698 420737024 50262 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 413448

[startup+6.30547 s]
/proc/loadavg: 1.37 1.24 1.19 2/44 25564
/proc/meminfo: memFree=31672/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=439916 CPUtime=6.3
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 78235 0 1 0 599 31 0 0 25 0 9 0 46357695 450473984 77470 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 109979 77470 2902 10 0 104127 0
[pid=25555/tid=25557] ppid=25554 vsize=439916 CPUtime=2.29
/proc/25555/task/25557/stat : 25557 (java) R 25554 25554 17511 34816 17511 4202560 13878 0 1 0 223 6 0 0 25 0 9 0 46357696 450473984 77470 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=25555/tid=25558] ppid=25554 vsize=439916 CPUtime=3.94
/proc/25555/task/25558/stat : 25558 (java) R 25554 25554 17511 34816 17511 4202560 62948 0 0 0 370 24 0 0 16 0 9 0 46357696 450473984 77470 1283457024 134512640 134550932 4287154656 18446744073709551615 4152109595 0 0 0 16800975 0 0 0 -1 0 0 0 0
[pid=25555/tid=25559] ppid=25554 vsize=439916 CPUtime=0
/proc/25555/task/25559/stat : 25559 (java) S 25554 25554 17511 34816 17511 4202560 15 0 0 0 0 0 0 0 20 0 9 0 46357696 450473984 77470 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25560] ppid=25554 vsize=439916 CPUtime=0
/proc/25555/task/25560/stat : 25560 (java) S 25554 25554 17511 34816 17511 4202560 5 0 0 0 0 0 0 0 20 0 9 0 46357696 450473984 77470 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25561] ppid=25554 vsize=439916 CPUtime=0
/proc/25555/task/25561/stat : 25561 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 9 0 46357698 450473984 77470 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25562] ppid=25554 vsize=439916 CPUtime=0.05
/proc/25555/task/25562/stat : 25562 (java) S 25554 25554 17511 34816 17511 4202560 468 0 0 0 5 0 0 0 15 0 9 0 46357698 450473984 77470 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25563] ppid=25554 vsize=439916 CPUtime=0
/proc/25555/task/25563/stat : 25563 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 9 0 46357698 450473984 77470 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25564] ppid=25554 vsize=439916 CPUtime=0
/proc/25555/task/25564/stat : 25564 (java) S 25554 25554 17511 34816 17511 4202560 2 0 0 0 0 0 0 0 15 0 9 0 46357698 450473984 77470 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 442488

[startup+12.7073 s]
/proc/loadavg: 1.32 1.23 1.19 2/45 25565
/proc/meminfo: memFree=33784/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=411880 CPUtime=12.7
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 100038 0 1 0 1226 44 0 0 25 0 10 0 46357695 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102970 70650 2918 10 0 97115 0
[pid=25555/tid=25557] ppid=25554 vsize=411880 CPUtime=4.49
/proc/25555/task/25557/stat : 25557 (java) R 25554 25554 17511 34816 17511 4202560 14132 0 1 0 443 6 0 0 25 0 10 0 46357696 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4115181232 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=25555/tid=25558] ppid=25554 vsize=411880 CPUtime=8.08
/proc/25555/task/25558/stat : 25558 (java) S 25554 25554 17511 34816 17511 4202560 84418 0 0 0 772 36 0 0 16 0 10 0 46357696 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25559] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25559/stat : 25559 (java) S 25554 25554 17511 34816 17511 4202560 15 0 0 0 0 0 0 0 15 0 10 0 46357696 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25560] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25560/stat : 25560 (java) S 25554 25554 17511 34816 17511 4202560 5 0 0 0 0 0 0 0 18 0 10 0 46357696 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25561] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25561/stat : 25561 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 10 0 46357698 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25562] ppid=25554 vsize=411880 CPUtime=0.1
/proc/25555/task/25562/stat : 25562 (java) S 25554 25554 17511 34816 17511 4202560 543 0 0 0 10 0 0 0 15 0 10 0 46357698 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25563] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25563/stat : 25563 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 10 0 46357698 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25564] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25564/stat : 25564 (java) S 25554 25554 17511 34816 17511 4202560 2 0 0 0 0 0 0 0 15 0 10 0 46357698 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25565] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25565/stat : 25565 (java) S 25554 25554 17511 34816 17511 4202560 4 0 0 0 0 0 0 0 22 0 10 0 46358778 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 12.7
Current children cumulated vsize (KiB) 414452

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

[startup+12.8073 s]
/proc/loadavg: 1.32 1.23 1.19 2/45 25565
/proc/meminfo: memFree=33784/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=411880 CPUtime=12.8
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 100038 0 1 0 1236 44 0 0 25 0 10 0 46357695 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102970 70650 2918 10 0 97115 0
[pid=25555/tid=25557] ppid=25554 vsize=411880 CPUtime=4.59
/proc/25555/task/25557/stat : 25557 (java) R 25554 25554 17511 34816 17511 4202560 14132 0 1 0 453 6 0 0 25 0 10 0 46357696 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4115190688 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=25555/tid=25558] ppid=25554 vsize=411880 CPUtime=8.08
/proc/25555/task/25558/stat : 25558 (java) S 25554 25554 17511 34816 17511 4202560 84418 0 0 0 772 36 0 0 16 0 10 0 46357696 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25559] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25559/stat : 25559 (java) S 25554 25554 17511 34816 17511 4202560 15 0 0 0 0 0 0 0 15 0 10 0 46357696 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25560] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25560/stat : 25560 (java) S 25554 25554 17511 34816 17511 4202560 5 0 0 0 0 0 0 0 18 0 10 0 46357696 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25561] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25561/stat : 25561 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 10 0 46357698 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25562] ppid=25554 vsize=411880 CPUtime=0.1
/proc/25555/task/25562/stat : 25562 (java) S 25554 25554 17511 34816 17511 4202560 543 0 0 0 10 0 0 0 15 0 10 0 46357698 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25563] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25563/stat : 25563 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 10 0 46357698 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25564] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25564/stat : 25564 (java) S 25554 25554 17511 34816 17511 4202560 2 0 0 0 0 0 0 0 15 0 10 0 46357698 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25565] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25565/stat : 25565 (java) S 25554 25554 17511 34816 17511 4202560 4 0 0 0 0 0 0 0 22 0 10 0 46358778 421765120 70650 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 12.8
Current children cumulated vsize (KiB) 414452

[startup+14.4078 s]
/proc/loadavg: 1.32 1.23 1.19 2/45 25565
/proc/meminfo: memFree=33784/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=411880 CPUtime=14.4
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 100044 0 1 0 1396 44 0 0 25 0 10 0 46357695 421765120 70656 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102970 70656 2918 10 0 97115 0
[pid=25555/tid=25557] ppid=25554 vsize=411880 CPUtime=6.18
/proc/25555/task/25557/stat : 25557 (java) R 25554 25554 17511 34816 17511 4202560 14132 0 1 0 612 6 0 0 25 0 10 0 46357696 421765120 70656 1283457024 134512640 134550932 4287154656 18446744073709551615 4114344226 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=25555/tid=25558] ppid=25554 vsize=411880 CPUtime=8.08
/proc/25555/task/25558/stat : 25558 (java) S 25554 25554 17511 34816 17511 4202560 84418 0 0 0 772 36 0 0 15 0 10 0 46357696 421765120 70656 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25559] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25559/stat : 25559 (java) S 25554 25554 17511 34816 17511 4202560 15 0 0 0 0 0 0 0 15 0 10 0 46357696 421765120 70656 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25560] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25560/stat : 25560 (java) S 25554 25554 17511 34816 17511 4202560 5 0 0 0 0 0 0 0 18 0 10 0 46357696 421765120 70656 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25561] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25561/stat : 25561 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 10 0 46357698 421765120 70656 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25562] ppid=25554 vsize=411880 CPUtime=0.11
/proc/25555/task/25562/stat : 25562 (java) S 25554 25554 17511 34816 17511 4202560 549 0 0 0 11 0 0 0 16 0 10 0 46357698 421765120 70656 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25563] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25563/stat : 25563 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 10 0 46357698 421765120 70656 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25564] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25564/stat : 25564 (java) S 25554 25554 17511 34816 17511 4202560 2 0 0 0 0 0 0 0 15 0 10 0 46357698 421765120 70656 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25565] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25565/stat : 25565 (java) S 25554 25554 17511 34816 17511 4202560 4 0 0 0 0 0 0 0 22 0 10 0 46358778 421765120 70656 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 14.4
Current children cumulated vsize (KiB) 414452

[startup+15.208 s]
/proc/loadavg: 1.32 1.23 1.19 2/45 25565
/proc/meminfo: memFree=33784/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=411880 CPUtime=15.2
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 100046 0 1 0 1476 44 0 0 25 0 10 0 46357695 421765120 70658 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102970 70658 2918 10 0 97115 0
[pid=25555/tid=25557] ppid=25554 vsize=411880 CPUtime=6.98
/proc/25555/task/25557/stat : 25557 (java) R 25554 25554 17511 34816 17511 4202560 14132 0 1 0 692 6 0 0 25 0 10 0 46357696 421765120 70658 1283457024 134512640 134550932 4287154656 18446744073709551615 4115324489 0 4 0 16800975 0 0 0 -1 0 0 0 0
[pid=25555/tid=25558] ppid=25554 vsize=411880 CPUtime=8.08
/proc/25555/task/25558/stat : 25558 (java) S 25554 25554 17511 34816 17511 4202560 84418 0 0 0 772 36 0 0 16 0 10 0 46357696 421765120 70658 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25559] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25559/stat : 25559 (java) S 25554 25554 17511 34816 17511 4202560 15 0 0 0 0 0 0 0 15 0 10 0 46357696 421765120 70658 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25560] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25560/stat : 25560 (java) S 25554 25554 17511 34816 17511 4202560 5 0 0 0 0 0 0 0 18 0 10 0 46357696 421765120 70658 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25561] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25561/stat : 25561 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 10 0 46357698 421765120 70658 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25562] ppid=25554 vsize=411880 CPUtime=0.11
/proc/25555/task/25562/stat : 25562 (java) S 25554 25554 17511 34816 17511 4202560 551 0 0 0 11 0 0 0 15 0 10 0 46357698 421765120 70658 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25563] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25563/stat : 25563 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 10 0 46357698 421765120 70658 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25564] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25564/stat : 25564 (java) S 25554 25554 17511 34816 17511 4202560 2 0 0 0 0 0 0 0 15 0 10 0 46357698 421765120 70658 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25565] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25565/stat : 25565 (java) S 25554 25554 17511 34816 17511 4202560 4 0 0 0 0 0 0 0 22 0 10 0 46358778 421765120 70658 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 15.2
Current children cumulated vsize (KiB) 414452

[startup+15.601 s]
/proc/loadavg: 1.32 1.23 1.19 2/45 25565
/proc/meminfo: memFree=33784/1048576 swapFree=0/0
[pid=25554] ppid=25553 vsize=2572 CPUtime=0
/proc/25554/stat : 25554 (gj-user-solver-) S 25553 25554 17511 34816 17511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 46357695 2633728 270 1283457024 134512640 135304128 4286904896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/25554/statm: 643 270 229 194 0 30 0
[pid=25555] ppid=25554 vsize=411880 CPUtime=15.58
/proc/25555/stat : 25555 (java) S 25554 25554 17511 34816 17511 4202496 100049 0 1 0 1514 44 0 0 25 0 9 0 46357695 421765120 70661 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/25555/statm: 102970 70661 2921 10 0 97115 0
[pid=25555/tid=25557] ppid=25554 vsize=411880 CPUtime=7.32
/proc/25555/task/25557/stat : 25557 (java) S 25554 25554 17511 34816 17511 4202560 14132 0 1 0 726 6 0 0 25 0 9 0 46357696 421765120 70661 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25558] ppid=25554 vsize=411880 CPUtime=8.12
/proc/25555/task/25558/stat : 25558 (java) S 25554 25554 17511 34816 17511 4202560 84420 0 0 0 776 36 0 0 16 0 9 0 46357696 421765120 70661 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 0 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25559] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25559/stat : 25559 (java) S 25554 25554 17511 34816 17511 4202560 15 0 0 0 0 0 0 0 15 0 9 0 46357696 421765120 70661 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25560] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25560/stat : 25560 (java) S 25554 25554 17511 34816 17511 4202560 5 0 0 0 0 0 0 0 18 0 9 0 46357696 421765120 70661 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25561] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25561/stat : 25561 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 9 0 46357698 421765120 70661 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25562] ppid=25554 vsize=411880 CPUtime=0.11
/proc/25555/task/25562/stat : 25562 (java) S 25554 25554 17511 34816 17511 4202560 551 0 0 0 11 0 0 0 15 0 9 0 46357698 421765120 70661 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25563] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25563/stat : 25563 (java) S 25554 25554 17511 34816 17511 4202560 1 0 0 0 0 0 0 0 25 0 9 0 46357698 421765120 70661 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
[pid=25555/tid=25564] ppid=25554 vsize=411880 CPUtime=0
/proc/25555/task/25564/stat : 25564 (java) S 25554 25554 17511 34816 17511 4202560 2 0 0 0 0 0 0 0 15 0 9 0 46357698 421765120 70661 1283457024 134512640 134550932 4287154656 18446744073709551615 4294960130 0 4 0 16800975 18446612133393238784 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 15.58
Current children cumulated vsize (KiB) 414452

Child status: 0
Real time (s): 15.6418
CPU time (s): 15.601
CPU user time (s): 15.1449
CPU system time (s): 0.456028
CPU usage (%): 99.7388
Max. virtual memory (cumulated for all children) (KiB): 442488

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 15.1449
system time used= 0.456028
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 100438
page faults= 1
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1090
involuntary context switches= 1236

runsolver used 0 second user time and 0 second system time

The end