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/201108300820/aspcud-1.5/rand609.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand609.cudf /home/misc2010/tmp/201108300820/aspcud-1.5/rand609.cudf.user-upgrades.result +sum(installedsize) 

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.00 1.00 1.00 3/38 9773
/proc/meminfo: memFree=926012/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=0
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=2596 CPUtime=0
/proc/9771/stat : 9771 (aspcud-1.5) R 9763 9763 2160 34817 2160 4202560 110 0 0 0 0 0 0 0 25 0 1 0 54896422 2658304 131 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 0 6 1132494585 0 0 0 17 0 0 0 0
/proc/9771/statm: 649 131 83 194 0 36 0
[pid=9772] ppid=9763 vsize=2596 CPUtime=0
/proc/9772/stat : 9772 (aspcud-1.5) R 9763 9763 2160 34817 2160 4202560 110 0 0 0 0 0 0 0 25 0 1 0 54896422 2658304 131 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 0 6 1132494585 0 0 0 17 0 0 0 0
/proc/9772/statm: 649 131 83 194 0 36 0
[pid=9773] ppid=9763 vsize=2596 CPUtime=0
/proc/9773/stat : 9773 (aspcud-1.5) D 9763 9763 2160 34817 2160 4202560 109 0 0 0 0 0 0 0 25 0 1 0 54896423 2658304 130 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 0 6 1132494585 18446744071564252162 0 0 17 0 0 0 0
/proc/9773/statm: 649 130 82 194 0 36 0

[startup+0.151909 s]
/proc/loadavg: 1.00 1.00 1.00 3/38 9773
/proc/meminfo: memFree=926012/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=0
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=1788 CPUtime=0
/proc/9771/stat : 9771 (clasp) D 9763 9763 2160 34817 2160 4194304 137 0 5 0 0 0 0 0 24 0 1 0 54896422 1830912 12 1283457024 134512640 136285277 4289237904 18446744073709551615 135657968 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/9771/statm: 447 12 7 433 0 12 0
[pid=9772] ppid=9763 vsize=2436 CPUtime=0
/proc/9772/stat : 9772 (gringo) D 9763 9763 2160 34817 2160 4194304 135 0 3 0 0 0 0 0 24 0 1 0 54896422 2494464 8 1283457024 134512640 136933539 4289893392 18446744073709551615 136275864 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/9772/statm: 609 8 3 592 0 14 0
[pid=9773] ppid=9763 vsize=1300 CPUtime=0
/proc/9773/stat : 9773 (cudf2lp) D 9763 9763 2160 34817 2160 4194304 137 0 4 0 0 0 0 0 24 0 1 0 54896423 1331200 11 1283457024 134512640 135786343 4292560208 18446744073709551615 135406624 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/9773/statm: 325 11 5 311 0 12 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 8120

[startup+0.20791 s]
/proc/loadavg: 1.00 1.00 1.00 3/38 9773
/proc/meminfo: memFree=926012/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=0
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=1924 CPUtime=0
/proc/9771/stat : 9771 (clasp) D 9763 9763 2160 34817 2160 4202496 155 0 8 0 0 0 0 0 24 0 1 0 54896422 1970176 33 1283457024 134512640 136285277 4289237904 18446744073709551615 135964784 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/9771/statm: 481 33 25 433 0 46 0
[pid=9772] ppid=9763 vsize=2440 CPUtime=0
/proc/9772/stat : 9772 (gringo) D 9763 9763 2160 34817 2160 4194304 140 0 6 0 0 0 0 0 24 0 1 0 54896422 2498560 16 1283457024 134512640 136933539 4289893392 18446744073709551615 136205360 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/9772/statm: 610 16 10 592 0 15 0
[pid=9773] ppid=9763 vsize=1436 CPUtime=0
/proc/9773/stat : 9773 (cudf2lp) D 9763 9763 2160 34817 2160 4202496 159 0 7 0 0 0 0 0 24 0 1 0 54896423 1470464 36 1283457024 134512640 135786343 4292560208 18446744073709551615 135498528 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/9773/statm: 359 36 27 311 0 46 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 8396

[startup+0.307913 s]
/proc/loadavg: 1.00 1.00 1.00 3/38 9773
/proc/meminfo: memFree=926012/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=0
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=1928 CPUtime=0
/proc/9771/stat : 9771 (clasp) R 9763 9763 2160 34817 2160 4202496 223 0 16 0 0 0 0 0 23 0 1 0 54896422 1974272 107 1283457024 134512640 136285277 4289237904 18446744073709551615 134530640 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9771/statm: 482 107 96 433 0 47 0
[pid=9772] ppid=9763 vsize=2572 CPUtime=0
/proc/9772/stat : 9772 (gringo) R 9763 9763 2160 34817 2160 4202496 206 0 13 0 0 0 0 0 23 0 1 0 54896422 2633728 87 1283457024 134512640 136933539 4289893392 18446744073709551615 134942432 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9772/statm: 643 87 75 592 0 48 0
[pid=9773] ppid=9763 vsize=1440 CPUtime=0
/proc/9773/stat : 9773 (cudf2lp) D 9763 9763 2160 34817 2160 4202496 235 0 14 0 0 0 0 0 23 0 1 0 54896423 1474560 117 1283457024 134512640 135786343 4292560208 18446744073709551615 134868544 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/9773/statm: 360 117 103 311 0 47 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 8536

[startup+0.707934 s]
/proc/loadavg: 1.00 1.00 1.00 3/38 9773
/proc/meminfo: memFree=926012/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=0
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=1932 CPUtime=0
/proc/9771/stat : 9771 (clasp) S 9763 9763 2160 34817 2160 4202496 273 0 19 0 0 0 0 0 22 0 1 0 54896422 1978368 160 1283457024 134512640 136285277 4289237904 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9771/statm: 483 160 144 433 0 48 0
[pid=9772] ppid=9763 vsize=2584 CPUtime=0
/proc/9772/stat : 9772 (gringo) S 9763 9763 2160 34817 2160 4202496 381 0 23 0 0 0 0 0 22 0 1 0 54896422 2646016 272 1283457024 134512640 136933539 4289893392 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9772/statm: 646 272 242 592 0 51 0
[pid=9773] ppid=9763 vsize=9040 CPUtime=0.29
/proc/9773/stat : 9773 (cudf2lp) R 9763 9763 2160 34817 2160 4202496 2340 0 15 0 29 0 0 0 23 0 1 0 54896423 9256960 1912 1283457024 134512640 135786343 4292560208 18446744073709551615 134566184 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9773/statm: 2260 1912 128 311 0 1947 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 16152

[startup+1.50797 s]
/proc/loadavg: 1.24 1.05 1.02 2/39 9774
/proc/meminfo: memFree=898400/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=0
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=1932 CPUtime=0
/proc/9771/stat : 9771 (clasp) S 9763 9763 2160 34817 2160 4202496 273 0 19 0 0 0 0 0 22 0 1 0 54896422 1978368 160 1283457024 134512640 136285277 4289237904 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9771/statm: 483 160 144 433 0 48 0
[pid=9772] ppid=9763 vsize=2584 CPUtime=0
/proc/9772/stat : 9772 (gringo) S 9763 9763 2160 34817 2160 4202496 381 0 23 0 0 0 0 0 22 0 1 0 54896422 2646016 272 1283457024 134512640 136933539 4289893392 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9772/statm: 646 272 242 592 0 51 0
[pid=9773] ppid=9763 vsize=18568 CPUtime=0.98
/proc/9773/stat : 9773 (cudf2lp) R 9763 9763 2160 34817 2160 4202496 5460 0 15 0 98 0 0 0 25 0 1 0 54896423 19013632 4436 1283457024 134512640 135786343 4292560208 18446744073709551615 134566203 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9773/statm: 4642 4436 128 311 0 4329 0
Current children cumulated CPU time (s) 0.98
Current children cumulated vsize (KiB) 25680

[startup+3.10943 s]
/proc/loadavg: 1.24 1.05 1.02 2/39 9774
/proc/meminfo: memFree=870776/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=0
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=5712 CPUtime=0.01
/proc/9771/stat : 9771 (clasp) S 9763 9763 2160 34817 2160 4202496 1287 0 22 0 0 1 0 0 18 0 1 0 54896422 5849088 1095 1283457024 134512640 136285277 4289237904 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9771/statm: 1428 1095 177 433 0 993 0
[pid=9772] ppid=9763 vsize=7836 CPUtime=0.19
/proc/9772/stat : 9772 (gringo) R 9763 9763 2160 34817 2160 4202496 1846 0 23 0 19 0 0 0 18 0 1 0 54896422 8024064 1413 1283457024 134512640 136933539 4289893392 18446744073709551615 134750339 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9772/statm: 1959 1413 242 592 0 1364 0
[pid=9773] ppid=9763 vsize=44576 CPUtime=2.16
/proc/9773/stat : 9773 (cudf2lp) R 9763 9763 2160 34817 2160 4202496 13967 0 15 0 212 4 0 0 25 0 1 0 54896423 45645824 10945 1283457024 134512640 135786343 4292560208 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9773/statm: 11144 10945 139 311 0 10831 0
Current children cumulated CPU time (s) 2.36
Current children cumulated vsize (KiB) 60720
heavy processes:

[startup+6.31027 s]
/proc/loadavg: 1.30 1.07 1.02 3/39 9774
/proc/meminfo: memFree=770024/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=0
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=49756 CPUtime=0.21
/proc/9771/stat : 9771 (clasp) S 9763 9763 2160 34817 2160 4202496 14608 0 22 0 14 7 0 0 18 0 1 0 54896422 50950144 11816 1283457024 134512640 136285277 4289237904 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9771/statm: 12439 11816 177 433 0 12004 0
[pid=9772] ppid=9763 vsize=75352 CPUtime=2.65
/proc/9772/stat : 9772 (gringo) R 9763 9763 2160 34817 2160 4202496 22501 0 23 0 250 15 0 0 18 0 1 0 54896422 77160448 14593 1283457024 134512640 136933539 4289893392 18446744073709551615 136204829 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9772/statm: 18838 14593 242 592 0 18243 0
[pid=9773] ppid=9763 vsize=44576 CPUtime=2.68
/proc/9773/stat : 9773 (cudf2lp) R 9763 9763 2160 34817 2160 4202496 13967 0 15 0 263 5 0 0 25 0 1 0 54896423 45645824 10945 1283457024 134512640 135786343 4292560208 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9773/statm: 11144 10945 139 311 0 10831 0
Current children cumulated CPU time (s) 5.54
Current children cumulated vsize (KiB) 172280

[startup+12.7115 s]
/proc/loadavg: 1.28 1.06 1.02 2/38 9775
/proc/meminfo: memFree=541640/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=10.42
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 580 98881 0 38 0 0 1003 39 18 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=159056 CPUtime=1.54
/proc/9771/stat : 9771 (clasp) R 9763 9763 2160 34817 2160 4202496 46552 0 22 0 134 20 0 0 18 0 1 0 54896422 162873344 38477 1283457024 134512640 136285277 4289237904 18446744073709551615 135047248 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9771/statm: 39764 38477 188 433 0 39329 0
Current children cumulated CPU time (s) 11.96
Current children cumulated vsize (KiB) 161652

[startup+25.5145 s]
/proc/loadavg: 1.21 1.06 1.02 2/37 9776
/proc/meminfo: memFree=634656/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=10.42
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 580 98881 0 38 0 0 1003 39 18 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=264632 CPUtime=14.34
/proc/9771/stat : 9771 (clasp) R 9763 9763 2160 34817 2160 4202496 80842 0 22 0 1400 34 0 0 25 0 1 0 54896422 270983168 65874 1283457024 134512640 136285277 4289237904 18446744073709551615 134723291 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9771/statm: 66158 65874 234 433 0 65723 0
Current children cumulated CPU time (s) 24.76
Current children cumulated vsize (KiB) 267228

[startup+51.1104 s]
/proc/loadavg: 1.14 1.05 1.02 2/36 9778
/proc/meminfo: memFree=116848/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=10.42
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 580 98881 0 38 0 0 1003 39 18 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=787660 CPUtime=39.9
/proc/9771/stat : 9771 (clasp) R 9763 9763 2160 34817 2160 4202496 211586 0 22 0 3923 67 0 0 25 0 1 0 54896422 806563840 196618 1283457024 134512640 136285277 4289237904 18446744073709551615 134964942 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9771/statm: 196915 196618 234 433 0 196480 0
Current children cumulated CPU time (s) 50.32
Current children cumulated vsize (KiB) 790256

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

[startup+57.5119 s]
/proc/loadavg: 1.13 1.05 1.02 2/36 9778
/proc/meminfo: memFree=5232/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=10.42
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 580 98881 0 38 0 0 1003 39 18 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=905468 CPUtime=46.29
/proc/9771/stat : 9771 (clasp) R 9763 9763 2160 34817 2160 4202496 241041 0 22 0 4552 77 0 0 25 0 1 0 54896422 927199232 226073 1283457024 134512640 136285277 4289237904 18446744073709551615 134669866 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9771/statm: 226367 226073 234 433 0 225932 0
Current children cumulated CPU time (s) 56.71
Current children cumulated vsize (KiB) 908064

[startup+60.7074 s]
/proc/loadavg: 1.20 1.07 1.02 2/36 9778
/proc/meminfo: memFree=4272/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=10.42
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 580 98881 0 38 0 0 1003 39 18 0 1 0 54896422 2658304 298 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 298 251 194 0 36 0
[pid=9771] ppid=9763 vsize=964988 CPUtime=49.39
/proc/9771/stat : 9771 (clasp) R 9763 9763 2160 34817 2160 4202496 255932 0 22 0 4857 82 0 0 25 0 1 0 54896422 988147712 240964 1283457024 134512640 136285277 4289237904 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9771/statm: 241247 240964 234 433 0 240812 0
Current children cumulated CPU time (s) 59.81
Current children cumulated vsize (KiB) 967584

[startup+61.5076 s]
/proc/loadavg: 1.20 1.07 1.02 2/36 9778
/proc/meminfo: memFree=4160/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=10.42
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 580 98881 0 38 0 0 1003 39 18 0 1 0 54896422 2658304 297 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 297 250 194 0 36 0
[pid=9771] ppid=9763 vsize=980968 CPUtime=50.19
/proc/9771/stat : 9771 (clasp) R 9763 9763 2160 34817 2160 4202496 259919 0 22 0 4933 86 0 0 25 0 1 0 54896422 1004511232 244951 1283457024 134512640 136285277 4289237904 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9771/statm: 245242 244951 234 433 0 244807 0
Current children cumulated CPU time (s) 60.61
Current children cumulated vsize (KiB) 983564

[startup+62.6038 s]
/proc/loadavg: 1.20 1.07 1.02 2/36 9778
/proc/meminfo: memFree=4160/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=61.02
/proc/9763/stat : 9763 (aspcud-1.5) D 9762 9763 2160 34817 2160 4202496 590 359694 6 90 0 0 5952 150 18 0 1 0 54896422 2658304 64 1283457024 134512640 135304128 4291317408 18446744073709551615 4160295424 0 65536 4 1132560123 18446744071564252162 0 0 17 0 0 0 0
/proc/9763/statm: 649 64 17 194 0 36 0
Current children cumulated CPU time (s) 61.02
Current children cumulated vsize (KiB) 2596

[startup+62.8078 s]
/proc/loadavg: 1.20 1.07 1.02 2/36 9778
/proc/meminfo: memFree=4160/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2596 CPUtime=61.02
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 735 359694 18 90 0 0 5952 150 18 0 1 0 54896422 2658304 203 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 649 203 156 194 0 36 0
Current children cumulated CPU time (s) 61.02
Current children cumulated vsize (KiB) 2596

[startup+62.9078 s]
/proc/loadavg: 1.20 1.07 1.02 2/36 9778
/proc/meminfo: memFree=4160/1048576 swapFree=0/0
[pid=9763] ppid=9762 vsize=2600 CPUtime=61.02
/proc/9763/stat : 9763 (aspcud-1.5) S 9762 9763 2160 34817 2160 4202496 939 361280 18 100 0 0 5952 150 23 0 1 0 54896422 2662400 225 1283457024 134512640 135304128 4291317408 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/9763/statm: 650 225 177 194 0 37 0
Current children cumulated CPU time (s) 61.02
Current children cumulated vsize (KiB) 2600

Child status: 0
Real time (s): 62.9277
CPU time (s): 61.0358
CPU user time (s): 59.5277
CPU system time (s): 1.50809
CPU usage (%): 96.9935
Max. virtual memory (cumulated for all children) (KiB): 986632

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 59.5277
system time used= 1.50809
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 363054
page faults= 119
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 13211
involuntary context switches= 12180

runsolver used 0 second user time and 0.100006 second system time

The end