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/paranoid-size/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/paranoid-size/real/7c834c0e-51b8-11e0-a49e-00163e1e087d.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

[startup+0 s]
/proc/loadavg: 0.89 0.95 0.83 2/60 3842
/proc/meminfo: memFree=352456/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=3152 CPUtime=0
/proc/3842/stat : 3842 (runsolver) R 3841 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115327551 3227648 32 18446744073709551615 134512640 134586868 4291991088 4291989136 4151272496 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.172721 s]
/proc/loadavg: 0.89 0.95 0.83 2/60 3842
/proc/meminfo: memFree=352456/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=0.03
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 730 3613 0 0 0 0 3 0 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493760 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200259 s]
/proc/loadavg: 0.89 0.95 0.83 2/60 3842
/proc/meminfo: memFree=352456/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=0.03
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 730 3613 0 0 0 0 3 0 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493760 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300279 s]
/proc/loadavg: 0.89 0.95 0.83 2/60 3842
/proc/meminfo: memFree=352456/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=0.03
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 730 3613 0 0 0 0 3 0 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493760 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700189 s]
/proc/loadavg: 0.89 0.95 0.83 2/60 3842
/proc/meminfo: memFree=352456/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=0.03
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 730 3613 0 0 0 0 3 0 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493760 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 0.89 0.95 0.83 2/62 3858
/proc/meminfo: memFree=292912/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=0.03
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 730 3613 0 0 0 0 3 0 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493760 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3858] ppid=3842 vsize=62748 CPUtime=1.42
/proc/3858/stat : 3858 (cudf2lp) R 3842 3842 1750 0 -1 4202496 20930 0 0 0 134 8 0 0 20 0 1 0 115327553 64253952 15393 18446744073709551615 4194304 5690517 140737240486912 140737240484360 4951809 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/3858/statm: 15687 15393 174 366 0 15318 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 71960

[startup+3.10025 s]
/proc/loadavg: 0.90 0.95 0.83 2/62 3859
/proc/meminfo: memFree=288696/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=1.49
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 755 24545 0 0 0 0 140 9 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493760 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3859] ppid=3842 vsize=171496 CPUtime=1.55
/proc/3859/stat : 3859 (gringo) R 3842 3842 1750 0 -1 4202496 41178 0 0 0 142 13 0 0 20 0 1 0 115327705 175611904 36509 18446744073709551615 4194304 6531320 140735602382448 140735602378728 4596736 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3859/statm: 42874 36509 283 571 0 42295 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 180708

[startup+6.30031 s]
/proc/loadavg: 0.90 0.95 0.83 2/63 3861
/proc/meminfo: memFree=259424/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=63128 CPUtime=2.66
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 18285 0 0 0 260 6 0 0 20 0 1 0 115327912 64643072 15413 18446744073709551615 4194304 6238623 140733863194608 140733863191632 4407011 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 15782 15413 264 500 0 15279 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 94380

[startup+12.7003 s]
/proc/loadavg: 0.91 0.95 0.83 2/63 3861
/proc/meminfo: memFree=259424/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=63128 CPUtime=9.01
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 18285 0 0 0 895 6 0 0 20 0 1 0 115327912 64643072 15413 18446744073709551615 4194304 6238623 140733863194608 140733863191632 4407044 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 15782 15413 264 500 0 15279 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.56
Current children cumulated vsize (KiB) 94380

[startup+25.5003 s]
/proc/loadavg: 0.93 0.96 0.83 2/63 3861
/proc/meminfo: memFree=259424/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=63128 CPUtime=21.72
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 18285 0 0 0 2166 6 0 0 20 0 1 0 115327912 64643072 15413 18446744073709551615 4194304 6238623 140733863194608 140733863191632 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 15782 15413 264 500 0 15279 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.27
Current children cumulated vsize (KiB) 94380

[startup+51.1003 s]
/proc/loadavg: 1.09 0.99 0.85 2/63 3861
/proc/meminfo: memFree=259424/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=63128 CPUtime=47.15
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 18285 0 0 0 4709 6 0 0 20 0 1 0 115327912 64643072 15413 18446744073709551615 4194304 6238623 140733863194608 140733863191632 4687704 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 15782 15413 264 500 0 15279 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.7
Current children cumulated vsize (KiB) 94380

[startup+102.3 s]
/proc/loadavg: 1.04 0.99 0.85 2/63 3861
/proc/meminfo: memFree=241072/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=81328 CPUtime=98.01
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 22867 0 0 0 9793 8 0 0 20 0 1 0 115327912 83279872 19995 18446744073709551615 4194304 6238623 140733863194608 140733863191632 4407036 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 20332 19995 264 500 0 19829 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.56
Current children cumulated vsize (KiB) 112580

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

[startup+102.403 s]
/proc/loadavg: 1.04 0.99 0.85 2/63 3861
/proc/meminfo: memFree=241072/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=81328 CPUtime=98.11
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 22867 0 0 0 9803 8 0 0 20 0 1 0 115327912 83279872 19995 18446744073709551615 4194304 6238623 140733863194608 140733863191632 4407084 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 20332 19995 264 500 0 19829 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.66
Current children cumulated vsize (KiB) 112580

[startup+115.2 s]
/proc/loadavg: 1.03 0.99 0.85 2/63 3861
/proc/meminfo: memFree=214908/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=108732 CPUtime=110.82
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 29698 0 0 0 11071 11 0 0 20 0 1 0 115327912 111341568 26826 18446744073709551615 4194304 6238623 140733863194608 140733863191632 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 27183 26826 264 500 0 26680 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 114.37
Current children cumulated vsize (KiB) 139984

[startup+121.6 s]
/proc/loadavg: 1.03 0.99 0.85 2/63 3861
/proc/meminfo: memFree=195812/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=129404 CPUtime=117.18
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 34881 0 0 0 11705 13 0 0 20 0 1 0 115327912 132509696 32009 18446744073709551615 4194304 6238623 140733863194608 140733863191160 4687707 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 32351 32009 264 500 0 31848 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 120.73
Current children cumulated vsize (KiB) 160656

[startup+123.2 s]
/proc/loadavg: 1.02 0.99 0.85 2/63 3861
/proc/meminfo: memFree=189612/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=133012 CPUtime=118.76
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 35768 0 0 0 11863 13 0 0 20 0 1 0 115327912 136204288 32896 18446744073709551615 4194304 6238623 140733863194608 140733863191160 4654160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 33253 32896 264 500 0 32750 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 122.31
Current children cumulated vsize (KiB) 164264

[startup+124.8 s]
/proc/loadavg: 1.02 0.99 0.85 2/63 3861
/proc/meminfo: memFree=189612/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=133012 CPUtime=120.35
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 35768 0 0 0 12022 13 0 0 20 0 1 0 115327912 136204288 32896 18446744073709551615 4194304 6238623 140733863194608 140733863191632 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 33253 32896 264 500 0 32750 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 123.9
Current children cumulated vsize (KiB) 164264

[startup+125.2 s]
/proc/loadavg: 1.02 0.99 0.85 2/63 3861
/proc/meminfo: memFree=189612/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=133012 CPUtime=120.75
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 35768 0 0 0 12062 13 0 0 20 0 1 0 115327912 136204288 32896 18446744073709551615 4194304 6238623 140733863194608 140733863191632 4676760 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 33253 32896 264 500 0 32750 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 124.3
Current children cumulated vsize (KiB) 164264

[startup+125.4 s]
/proc/loadavg: 1.02 0.99 0.85 2/63 3861
/proc/meminfo: memFree=189612/1022884 swapFree=0/0
[pid=3842] ppid=3841 vsize=9212 CPUtime=3.54
/proc/3842/stat : 3842 (aspcud-basic) S 3841 3842 1750 0 -1 4202496 794 73914 0 0 0 0 324 30 20 0 1 0 115327551 9433088 364 18446744073709551615 4194304 5129932 140735994495104 140735994493168 139743987016798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3842/statm: 2303 364 303 229 0 63 0
[pid=3860] ppid=3842 vsize=133012 CPUtime=120.95
/proc/3860/stat : 3860 (clasp) R 3842 3842 1750 0 -1 4202496 35768 0 0 0 12082 13 0 0 20 0 1 0 115327912 136204288 32896 18446744073709551615 4194304 6238623 140733863194608 140733863191632 5497897 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3860/statm: 33253 32896 264 500 0 32750 0
[pid=3861] ppid=3842 vsize=22040 CPUtime=0.01
/proc/3861/stat : 3861 (parse.py) S 3842 3842 1750 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 115327912 22568960 1128 18446744073709551615 4194304 6642060 140736158883824 140736158882184 140057345402656 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3861/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 124.5
Current children cumulated vsize (KiB) 164264

Child status: 0
Real time (s): 125.455
CPU time (s): 124.588
CPU user time (s): 124.088
CPU system time (s): 0.500031
CPU usage (%): 99.309
Max. virtual memory (cumulated for all children) (KiB): 217856

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 124.088
system time used= 0.500031
maximum resident set size= 178784
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 112140
page faults= 0
swaps= 0
block input operations= 34072
block output operations= 24088
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 82
involuntary context switches= 14269

runsolver used 0.228014 second user time and 0.416026 second system time

The end