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/ed1cc19e-51b7-11e0-8436-00163e1e087d.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/ed1cc19e-51b7-11e0-8436-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/real/ed1cc19e-51b7-11e0-8436-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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.91 0.92 0.94 2/56 9470
/proc/meminfo: memFree=366724/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9204 CPUtime=0
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 430 0 0 0 0 0 0 0 20 0 1 0 37578348 9424896 331 18446744073709551615 4194304 5129932 140736039079248 140736039076712 140728790542112 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2301 331 272 229 0 61 0

[startup+0.108965 s]
/proc/loadavg: 0.91 0.92 0.94 2/56 9470
/proc/meminfo: memFree=366724/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=0.04
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 729 3623 0 0 0 0 4 0 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077904 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200312 s]
/proc/loadavg: 0.91 0.92 0.94 2/56 9470
/proc/meminfo: memFree=366724/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=0.04
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 729 3623 0 0 0 0 4 0 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077904 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.30031 s]
/proc/loadavg: 0.91 0.92 0.94 2/56 9470
/proc/meminfo: memFree=366724/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=0.04
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 729 3623 0 0 0 0 4 0 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077904 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.70023 s]
/proc/loadavg: 0.91 0.92 0.94 2/56 9470
/proc/meminfo: memFree=366724/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=0.04
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 729 3623 0 0 0 0 4 0 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077904 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.91 0.92 0.94 2/58 9486
/proc/meminfo: memFree=329624/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=0.04
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 729 3623 0 0 0 0 4 0 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077904 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9486] ppid=9470 vsize=50356 CPUtime=1.44
/proc/9486/stat : 9486 (cudf2lp) R 9470 9470 32685 0 -1 4202496 14214 0 0 0 139 5 0 0 20 0 1 0 37578351 51564544 10815 18446744073709551615 4194304 5690517 140733333702560 140733333700200 4443936 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/9486/statm: 12589 10815 160 366 0 12220 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 59568

[startup+3.10023 s]
/proc/loadavg: 0.91 0.92 0.94 2/58 9486
/proc/meminfo: memFree=283124/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=2.25
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 754 24557 0 0 0 0 214 11 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077904 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.25
Current children cumulated vsize (KiB) 9212
heavy processes:

[startup+6.3004 s]
/proc/loadavg: 0.91 0.92 0.94 2/59 9489
/proc/meminfo: memFree=310024/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=59768 CPUtime=0.9
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 17240 0 0 0 86 4 0 0 20 0 1 0 37578884 61202432 14505 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 14942 14505 263 500 0 14439 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 91020

[startup+12.7004 s]
/proc/loadavg: 0.93 0.93 0.94 2/59 9489
/proc/meminfo: memFree=277412/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=59768 CPUtime=7.26
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 17291 0 0 0 722 4 0 0 20 0 1 0 37578884 61202432 14556 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4406990 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 14942 14556 263 500 0 14439 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 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.94 0.93 0.94 2/59 9489
/proc/meminfo: memFree=277164/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=59768 CPUtime=19.98
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 17359 0 0 0 1994 4 0 0 20 0 1 0 37578884 61202432 14624 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4406979 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 14942 14624 263 500 0 14439 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.29
Current children cumulated vsize (KiB) 91020

[startup+51.1003 s]
/proc/loadavg: 0.96 0.93 0.94 2/59 9492
/proc/meminfo: memFree=277164/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=59768 CPUtime=45.44
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 17359 0 0 0 4539 5 0 0 20 0 1 0 37578884 61202432 14624 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4663099 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 14942 14624 263 500 0 14439 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.75
Current children cumulated vsize (KiB) 91020

[startup+102.3 s]
/proc/loadavg: 0.98 0.94 0.94 2/59 9500
/proc/meminfo: memFree=276916/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=59768 CPUtime=96.35
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 17359 0 0 0 9627 8 0 0 20 0 1 0 37578884 61202432 14624 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4422007 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 14942 14624 263 500 0 14439 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.66
Current children cumulated vsize (KiB) 91020

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

[startup+102.403 s]
/proc/loadavg: 0.98 0.94 0.94 2/59 9500
/proc/meminfo: memFree=276916/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=59768 CPUtime=96.45
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 17359 0 0 0 9637 8 0 0 20 0 1 0 37578884 61202432 14624 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4407044 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 14942 14624 263 500 0 14439 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.76
Current children cumulated vsize (KiB) 91020

[startup+128 s]
/proc/loadavg: 0.99 0.95 0.94 2/59 9500
/proc/meminfo: memFree=269104/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=67824 CPUtime=121.92
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 19397 0 0 0 12181 11 0 0 20 0 1 0 37578884 69451776 16662 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 16956 16662 263 500 0 16453 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 127.23
Current children cumulated vsize (KiB) 99076

[startup+134.4 s]
/proc/loadavg: 0.99 0.95 0.94 2/59 9500
/proc/meminfo: memFree=269104/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=67824 CPUtime=128.28
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 19397 0 0 0 12817 11 0 0 20 0 1 0 37578884 69451776 16662 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 16956 16662 263 500 0 16453 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 133.59
Current children cumulated vsize (KiB) 99076

[startup+140.8 s]
/proc/loadavg: 0.99 0.95 0.94 2/59 9500
/proc/meminfo: memFree=269104/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=67824 CPUtime=134.65
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 19397 0 0 0 13454 11 0 0 20 0 1 0 37578884 69451776 16662 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4407002 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 16956 16662 263 500 0 16453 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 139.96
Current children cumulated vsize (KiB) 99076

[startup+142.4 s]
/proc/loadavg: 0.99 0.95 0.94 2/59 9500
/proc/meminfo: memFree=269104/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=67824 CPUtime=136.24
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 19397 0 0 0 13613 11 0 0 20 0 1 0 37578884 69451776 16662 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 16956 16662 263 500 0 16453 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 141.55
Current children cumulated vsize (KiB) 99076

[startup+144 s]
/proc/loadavg: 0.99 0.95 0.94 2/59 9500
/proc/meminfo: memFree=269104/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=67824 CPUtime=137.83
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 19397 0 0 0 13772 11 0 0 20 0 1 0 37578884 69451776 16662 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4355623 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 16956 16662 263 500 0 16453 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 143.14
Current children cumulated vsize (KiB) 99076

[startup+144.4 s]
/proc/loadavg: 0.99 0.95 0.94 2/59 9500
/proc/meminfo: memFree=269104/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=67824 CPUtime=138.23
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 19397 0 0 0 13812 11 0 0 20 0 1 0 37578884 69451776 16662 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 16956 16662 263 500 0 16453 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 143.54
Current children cumulated vsize (KiB) 99076

[startup+144.8 s]
/proc/loadavg: 0.99 0.95 0.94 2/59 9500
/proc/meminfo: memFree=269104/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=67824 CPUtime=138.63
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 19397 0 0 0 13852 11 0 0 20 0 1 0 37578884 69451776 16662 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4407011 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 16956 16662 263 500 0 16453 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 143.94
Current children cumulated vsize (KiB) 99076

[startup+144.9 s]
/proc/loadavg: 0.99 0.95 0.94 2/59 9500
/proc/meminfo: memFree=269104/1022884 swapFree=0/0
[pid=9470] ppid=9469 vsize=9212 CPUtime=5.3
/proc/9470/stat : 9470 (aspcud-basic) S 9469 9470 32685 0 -1 4202496 792 70972 0 0 0 0 494 36 20 0 1 0 37578348 9433088 364 18446744073709551615 4194304 5129932 140736039079248 140736039077312 140728790398046 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9470/statm: 2303 364 303 229 0 63 0
[pid=9488] ppid=9470 vsize=67824 CPUtime=138.73
/proc/9488/stat : 9488 (clasp) R 9470 9470 32685 0 -1 4202496 19397 0 0 0 13862 11 0 0 20 0 1 0 37578884 69451776 16662 18446744073709551615 4194304 6238623 140735540443568 140735540440592 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9488/statm: 16956 16662 263 500 0 16453 0
[pid=9489] ppid=9470 vsize=22040 CPUtime=0.01
/proc/9489/stat : 9489 (parse.py) S 9470 9470 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37578884 22568960 1127 18446744073709551615 4194304 6642060 140734993098816 140734993097176 139673892423456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9489/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 144.04
Current children cumulated vsize (KiB) 99076

Child status: 0
Real time (s): 144.992
CPU time (s): 144.169
CPU user time (s): 143.645
CPU system time (s): 0.524032
CPU usage (%): 99.4324
Max. virtual memory (cumulated for all children) (KiB): 203516

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 143.645
system time used= 0.524032
maximum resident set size= 166972
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 92788
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= 67
involuntary context switches= 2190

runsolver used 0.284017 second user time and 0.496031 second system time

The end