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/8afdd89e-51b8-11e0-acd7-00163e1e087d.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/real/8afdd89e-51b8-11e0-acd7-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/real/8afdd89e-51b8-11e0-acd7-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: 1.02 0.99 0.78 2/65 3710
/proc/meminfo: memFree=203596/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=3152 CPUtime=0
/proc/3710/stat : 3710 (runsolver) R 3709 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115269191 3227648 32 18446744073709551615 134512640 134586868 4288275408 4288273456 4151608368 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.125751 s]
/proc/loadavg: 1.02 0.99 0.78 2/65 3710
/proc/meminfo: memFree=203596/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=0.02
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 735 3618 0 0 0 0 2 0 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133635152 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200262 s]
/proc/loadavg: 1.02 0.99 0.78 2/65 3710
/proc/meminfo: memFree=203596/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=0.02
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 735 3618 0 0 0 0 2 0 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133635152 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300255 s]
/proc/loadavg: 1.02 0.99 0.78 2/65 3710
/proc/meminfo: memFree=203596/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=0.02
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 735 3618 0 0 0 0 2 0 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133635152 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700189 s]
/proc/loadavg: 1.02 0.99 0.78 2/65 3710
/proc/meminfo: memFree=203596/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=0.02
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 735 3618 0 0 0 0 2 0 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133635152 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 1.02 0.99 0.78 2/67 3726
/proc/meminfo: memFree=144672/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=0.02
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 735 3618 0 0 0 0 2 0 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133635152 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3726] ppid=3710 vsize=62748 CPUtime=1.43
/proc/3726/stat : 3726 (cudf2lp) R 3710 3710 1745 0 -1 4202496 20931 0 0 0 133 10 0 0 20 0 1 0 115269193 64253952 15394 18446744073709551615 4194304 5690517 140734230932336 140734230929784 4970346 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/3726/statm: 15687 15394 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: 1.02 0.99 0.78 2/67 3727
/proc/meminfo: memFree=146904/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=1.53
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 760 24551 0 0 0 0 141 12 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133635152 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3727] ppid=3710 vsize=162892 CPUtime=1.51
/proc/3727/stat : 3727 (gringo) R 3710 3710 1745 0 -1 4202496 39223 0 0 0 137 14 0 0 20 0 1 0 115269348 166801408 34554 18446744073709551615 4194304 6531320 140736789885104 140736789881528 4881736 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3727/statm: 40723 34554 283 571 0 40144 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 172104

[startup+6.30031 s]
/proc/loadavg: 1.02 0.99 0.78 2/68 3729
/proc/meminfo: memFree=124804/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=63128 CPUtime=2.6
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 18286 0 0 0 258 2 0 0 20 0 1 0 115269556 64643072 15413 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 15782 15413 264 500 0 15279 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 6.19
Current children cumulated vsize (KiB) 94380

[startup+12.7003 s]
/proc/loadavg: 1.02 0.99 0.78 2/68 3729
/proc/meminfo: memFree=124680/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=63128 CPUtime=8.96
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 18286 0 0 0 894 2 0 0 20 0 1 0 115269556 64643072 15413 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4406990 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 15782 15413 264 500 0 15279 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 94380

[startup+25.5004 s]
/proc/loadavg: 1.01 0.99 0.78 2/68 3729
/proc/meminfo: memFree=124680/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=63128 CPUtime=21.67
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 18286 0 0 0 2164 3 0 0 20 0 1 0 115269556 64643072 15413 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4407084 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 15782 15413 264 500 0 15279 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.26
Current children cumulated vsize (KiB) 94380

[startup+51.1003 s]
/proc/loadavg: 1.01 0.99 0.79 2/68 3729
/proc/meminfo: memFree=124680/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=63128 CPUtime=47.09
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 18286 0 0 0 4706 3 0 0 20 0 1 0 115269556 64643072 15413 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 15782 15413 264 500 0 15279 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.68
Current children cumulated vsize (KiB) 94380

[startup+102.3 s]
/proc/loadavg: 1.00 0.99 0.80 2/68 3729
/proc/meminfo: memFree=106328/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=81328 CPUtime=97.91
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 22868 0 0 0 9784 7 0 0 20 0 1 0 115269556 83279872 19995 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4687697 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 20332 19995 264 500 0 19829 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.5
Current children cumulated vsize (KiB) 112580

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

[startup+102.404 s]
/proc/loadavg: 1.00 0.99 0.80 2/68 3729
/proc/meminfo: memFree=106328/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=81328 CPUtime=98.01
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 22868 0 0 0 9794 7 0 0 20 0 1 0 115269556 83279872 19995 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4687697 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 20332 19995 264 500 0 19829 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.6
Current children cumulated vsize (KiB) 112580

[startup+115.2 s]
/proc/loadavg: 1.00 0.99 0.80 2/68 3729
/proc/meminfo: memFree=85992/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=103120 CPUtime=110.71
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 28319 0 0 0 11061 10 0 0 20 0 1 0 115269556 105594880 25446 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4371503 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 25780 25446 264 500 0 25277 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 114.3
Current children cumulated vsize (KiB) 134372

[startup+121.6 s]
/proc/loadavg: 1.00 0.99 0.80 2/68 3729
/proc/meminfo: memFree=69500/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=119848 CPUtime=117.06
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 32485 0 0 0 11694 12 0 0 20 0 1 0 115269556 122724352 29612 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 29962 29612 264 500 0 29459 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 120.65
Current children cumulated vsize (KiB) 151100

[startup+124.8 s]
/proc/loadavg: 1.00 0.99 0.80 2/68 3729
/proc/meminfo: memFree=57596/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=131296 CPUtime=120.24
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 35338 0 0 0 12008 16 0 0 20 0 1 0 115269556 134447104 32465 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4407106 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 32824 32465 264 500 0 32321 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 123.83
Current children cumulated vsize (KiB) 162548

[startup+126.4 s]
/proc/loadavg: 1.00 0.99 0.80 2/68 3729
/proc/meminfo: memFree=55364/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=133012 CPUtime=121.83
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 35769 0 0 0 12167 16 0 0 20 0 1 0 115269556 136204288 32896 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4332654 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 33253 32896 264 500 0 32750 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 125.42
Current children cumulated vsize (KiB) 164264

[startup+127.2 s]
/proc/loadavg: 1.00 0.99 0.80 2/68 3729
/proc/meminfo: memFree=54868/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=133012 CPUtime=122.63
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 35769 0 0 0 12247 16 0 0 20 0 1 0 115269556 136204288 32896 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4329920 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 33253 32896 264 500 0 32750 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 126.22
Current children cumulated vsize (KiB) 164264

[startup+127.6 s]
/proc/loadavg: 1.00 0.99 0.80 2/68 3729
/proc/meminfo: memFree=54868/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=133012 CPUtime=123.03
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 35769 0 0 0 12287 16 0 0 20 0 1 0 115269556 136204288 32896 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4685008 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 33253 32896 264 500 0 32750 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 126.62
Current children cumulated vsize (KiB) 164264

[startup+127.8 s]
/proc/loadavg: 1.00 0.99 0.80 2/68 3729
/proc/meminfo: memFree=54868/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=133012 CPUtime=123.22
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 35769 0 0 0 12306 16 0 0 20 0 1 0 115269556 136204288 32896 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4306761 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 33253 32896 264 500 0 32750 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 126.81
Current children cumulated vsize (KiB) 164264

[startup+127.9 s]
/proc/loadavg: 1.00 0.99 0.80 2/68 3729
/proc/meminfo: memFree=54868/1022884 swapFree=0/0
[pid=3710] ppid=3709 vsize=9212 CPUtime=3.58
/proc/3710/stat : 3710 (aspcud-basic) S 3709 3710 1745 0 -1 4202496 799 73921 0 0 0 0 323 35 20 0 1 0 115269191 9433088 365 18446744073709551615 4194304 5129932 140737133636496 140737133634560 140317204927582 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3710/statm: 2303 365 303 229 0 63 0
[pid=3728] ppid=3710 vsize=133012 CPUtime=123.32
/proc/3728/stat : 3728 (clasp) R 3710 3710 1745 0 -1 4202496 35769 0 0 0 12316 16 0 0 20 0 1 0 115269556 136204288 32896 18446744073709551615 4194304 6238623 140733602484544 140733602481568 4424279 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/3728/statm: 33253 32896 264 500 0 32750 0
[pid=3729] ppid=3710 vsize=22040 CPUtime=0.01
/proc/3729/stat : 3729 (parse.py) S 3710 3710 1745 0 -1 4202496 1320 0 0 0 0 1 0 0 20 0 1 0 115269556 22568960 1128 18446744073709551615 4194304 6642060 140733275412880 140733275411240 140220280469280 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/3729/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 126.91
Current children cumulated vsize (KiB) 164264

Child status: 0
Real time (s): 127.988
CPU time (s): 127.02
CPU user time (s): 126.452
CPU system time (s): 0.568035
CPU usage (%): 99.2436
Max. virtual memory (cumulated for all children) (KiB): 218112

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 126.452
system time used= 0.568035
maximum resident set size= 178788
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 112155
page faults= 0
swaps= 0
block input operations= 34080
block output operations= 24088
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 77
involuntary context switches= 14577

runsolver used 0.224014 second user time and 0.48803 second system time

The end