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/aspcud-basic-1.7/embedded/real/7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/real/7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf.result -sum(solution,installedsize),-count(removed) 

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

[startup+0 s]
/proc/loadavg: 0.88 0.92 0.90 2/64 6176
/proc/meminfo: memFree=312544/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=3152 CPUtime=0
/proc/6176/stat : 6176 (runsolver) R 6175 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115902835 3227648 32 18446744073709551615 134512640 134586868 4289452048 4289450096 4151931952 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.140453 s]
/proc/loadavg: 0.88 0.92 0.90 2/64 6176
/proc/meminfo: memFree=312544/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=0.03
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 737 3614 0 0 0 0 3 0 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017888 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200307 s]
/proc/loadavg: 0.88 0.92 0.90 2/64 6176
/proc/meminfo: memFree=312544/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=0.03
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 737 3614 0 0 0 0 3 0 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017888 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300255 s]
/proc/loadavg: 0.88 0.92 0.90 2/64 6176
/proc/meminfo: memFree=312544/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=0.03
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 737 3614 0 0 0 0 3 0 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017888 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700219 s]
/proc/loadavg: 0.88 0.92 0.90 2/64 6176
/proc/meminfo: memFree=312544/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=0.03
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 737 3614 0 0 0 0 3 0 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017888 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 0.88 0.92 0.90 2/66 6192
/proc/meminfo: memFree=252008/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=0.03
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 737 3614 0 0 0 0 3 0 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017888 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6192] ppid=6176 vsize=73156 CPUtime=1.44
/proc/6192/stat : 6192 (cudf2lp) R 6176 6176 1745 0 -1 4202496 20197 0 0 0 136 8 0 0 20 0 1 0 115902837 74911744 16797 18446744073709551615 4194304 5690517 140737474069136 140737474066264 4271382 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/6192/statm: 18289 16797 168 366 0 17920 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 82368

[startup+3.10024 s]
/proc/loadavg: 0.88 0.92 0.90 2/66 6193
/proc/meminfo: memFree=270112/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=1.73
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 762 24549 0 0 0 0 162 11 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017888 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6193] ppid=6176 vsize=128900 CPUtime=1.32
/proc/6193/stat : 6193 (gringo) R 6176 6176 1745 0 -1 4202496 31584 0 0 0 122 10 0 0 20 0 1 0 115903011 131993600 26915 18446744073709551615 4194304 6531320 140734343684512 140734343681128 4358752 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/6193/statm: 32225 26915 283 571 0 31646 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 138112

[startup+6.3003 s]
/proc/loadavg: 0.89 0.92 0.90 2/67 6195
/proc/meminfo: memFree=222984/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=59768 CPUtime=2.5
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 17292 0 0 0 244 6 0 0 20 0 1 0 115903210 61202432 14557 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4356224 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 14942 14557 263 500 0 14439 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 91020

[startup+12.7003 s]
/proc/loadavg: 0.90 0.92 0.90 2/67 6195
/proc/meminfo: memFree=223232/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=59768 CPUtime=8.85
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 17360 0 0 0 878 7 0 0 20 0 1 0 115903210 61202432 14625 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4407044 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 14942 14625 263 500 0 14439 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.57
Current children cumulated vsize (KiB) 91020

[startup+25.5003 s]
/proc/loadavg: 0.92 0.92 0.90 2/67 6195
/proc/meminfo: memFree=222984/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=59768 CPUtime=21.56
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 17360 0 0 0 2149 7 0 0 20 0 1 0 115903210 61202432 14625 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4407165 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 14942 14625 263 500 0 14439 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.28
Current children cumulated vsize (KiB) 91020

[startup+51.1003 s]
/proc/loadavg: 0.95 0.93 0.91 2/67 6195
/proc/meminfo: memFree=222984/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=59768 CPUtime=46.96
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 17360 0 0 0 4688 8 0 0 20 0 1 0 115903210 61202432 14625 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4407068 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 14942 14625 263 500 0 14439 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.68
Current children cumulated vsize (KiB) 91020

[startup+102.3 s]
/proc/loadavg: 0.98 0.94 0.91 2/67 6195
/proc/meminfo: memFree=222860/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=59768 CPUtime=97.78
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 17360 0 0 0 9768 10 0 0 20 0 1 0 115903210 61202432 14625 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 14942 14625 263 500 0 14439 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.5
Current children cumulated vsize (KiB) 91020

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

[startup+102.404 s]
/proc/loadavg: 0.98 0.94 0.91 2/67 6195
/proc/meminfo: memFree=222860/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=59768 CPUtime=97.88
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 17360 0 0 0 9778 10 0 0 20 0 1 0 115903210 61202432 14625 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4586298 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 14942 14625 263 500 0 14439 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.6
Current children cumulated vsize (KiB) 91020

[startup+128 s]
/proc/loadavg: 0.98 0.94 0.91 2/67 6195
/proc/meminfo: memFree=214800/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=67824 CPUtime=123.28
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 19398 0 0 0 12315 13 0 0 20 0 1 0 115903210 69451776 16663 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4663125 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 16956 16663 263 500 0 16453 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 127
Current children cumulated vsize (KiB) 99076

[startup+134.4 s]
/proc/loadavg: 0.98 0.94 0.91 2/67 6195
/proc/meminfo: memFree=214800/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=67824 CPUtime=129.64
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 19398 0 0 0 12950 14 0 0 20 0 1 0 115903210 69451776 16663 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 16956 16663 263 500 0 16453 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 133.36
Current children cumulated vsize (KiB) 99076

[startup+140.8 s]
/proc/loadavg: 0.99 0.94 0.91 2/67 6195
/proc/meminfo: memFree=214800/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=67824 CPUtime=136
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 19398 0 0 0 13586 14 0 0 20 0 1 0 115903210 69451776 16663 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4663111 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 16956 16663 263 500 0 16453 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 139.72
Current children cumulated vsize (KiB) 99076

[startup+142.4 s]
/proc/loadavg: 0.99 0.94 0.91 2/67 6195
/proc/meminfo: memFree=214800/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=67824 CPUtime=137.58
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 19398 0 0 0 13744 14 0 0 20 0 1 0 115903210 69451776 16663 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4409910 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 16956 16663 263 500 0 16453 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 141.3
Current children cumulated vsize (KiB) 99076

[startup+143.2 s]
/proc/loadavg: 0.99 0.94 0.91 2/67 6195
/proc/meminfo: memFree=214800/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=67824 CPUtime=138.38
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 19398 0 0 0 13824 14 0 0 20 0 1 0 115903210 69451776 16663 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4407211 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 16956 16663 263 500 0 16453 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 142.1
Current children cumulated vsize (KiB) 99076

[startup+144 s]
/proc/loadavg: 0.99 0.94 0.91 2/67 6195
/proc/meminfo: memFree=214800/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=67824 CPUtime=139.17
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 19398 0 0 0 13903 14 0 0 20 0 1 0 115903210 69451776 16663 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4421820 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 16956 16663 263 500 0 16453 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 142.89
Current children cumulated vsize (KiB) 99076

[startup+144.4 s]
/proc/loadavg: 0.99 0.94 0.91 2/67 6195
/proc/meminfo: memFree=214800/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=67824 CPUtime=139.56
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 19398 0 0 0 13942 14 0 0 20 0 1 0 115903210 69451776 16663 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4356222 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 16956 16663 263 500 0 16453 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 143.28
Current children cumulated vsize (KiB) 99076

[startup+144.5 s]
/proc/loadavg: 0.99 0.94 0.91 2/67 6195
/proc/meminfo: memFree=214800/1022884 swapFree=0/0
[pid=6176] ppid=6175 vsize=9212 CPUtime=3.71
/proc/6176/stat : 6176 (aspcud-basic) S 6175 6176 1745 0 -1 4202496 801 70966 0 0 0 0 340 31 20 0 1 0 115902835 9433088 365 18446744073709551615 4194304 5129932 140733873019232 140733873017296 140723526788190 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6176/statm: 2303 365 303 229 0 63 0
[pid=6194] ppid=6176 vsize=67824 CPUtime=139.66
/proc/6194/stat : 6194 (clasp) R 6176 6176 1745 0 -1 4202496 19398 0 0 0 13952 14 0 0 20 0 1 0 115903210 69451776 16663 18446744073709551615 4194304 6238623 140734637191504 140734637188528 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/6194/statm: 16956 16663 263 500 0 16453 0
[pid=6195] ppid=6176 vsize=22040 CPUtime=0.01
/proc/6195/stat : 6195 (parse.py) S 6176 6176 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 115903210 22568960 1128 18446744073709551615 4194304 6642060 140735137024656 140735137023016 139915555305248 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/6195/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 143.38
Current children cumulated vsize (KiB) 99076

Child status: 0
Real time (s): 144.573
CPU time (s): 143.485
CPU user time (s): 142.993
CPU system time (s): 0.49203
CPU usage (%): 99.2476
Max. virtual memory (cumulated for all children) (KiB): 203516

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 142.993
system time used= 0.49203
maximum resident set size= 166976
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 92793
page faults= 0
swaps= 0
block input operations= 34072
block output operations= 22984
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 65
involuntary context switches= 16472

runsolver used 0.396024 second user time and 0.400025 second system time

The end