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 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/easy/rand583.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand583.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/easy/rand583.cudf.result -sum(changed,installedsize),-count(removed),-notuptodate(solution),-count(changed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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.01 1.00 1.00 2/64 20197
/proc/meminfo: memFree=243848/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=3152 CPUtime=0
/proc/20197/stat : 20197 (runsolver) R 20196 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120330981 3227648 32 18446744073709551615 134512640 134586868 4286946128 4286944176 4152177712 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.161952 s]
/proc/loadavg: 1.01 1.00 1.00 2/64 20197
/proc/meminfo: memFree=243848/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=0.03
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 741 3617 0 0 0 0 3 0 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017417360 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200397 s]
/proc/loadavg: 1.01 1.00 1.00 2/64 20197
/proc/meminfo: memFree=243848/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=0.03
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 741 3617 0 0 0 0 3 0 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017417360 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300273 s]
/proc/loadavg: 1.01 1.00 1.00 2/64 20197
/proc/meminfo: memFree=243848/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=0.03
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 741 3617 0 0 0 0 3 0 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017417360 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700229 s]
/proc/loadavg: 1.01 1.00 1.00 2/64 20197
/proc/meminfo: memFree=243848/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=0.03
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 741 3617 0 0 0 0 3 0 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017417360 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 1.01 1.00 1.00 2/66 20213
/proc/meminfo: memFree=202532/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=0.03
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 741 3617 0 0 0 0 3 0 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017417360 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20213] ppid=20197 vsize=48864 CPUtime=1.36
/proc/20213/stat : 20213 (cudf2lp) R 20197 20197 1745 0 -1 4202496 14027 0 0 0 130 6 0 0 20 0 1 0 120330984 50036736 10628 18446744073709551615 4194304 5690517 140733804007600 140733804005240 4348966 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/20213/statm: 12216 10628 159 366 0 11847 0
Current children cumulated CPU time (s) 1.39
Current children cumulated vsize (KiB) 58076

[startup+3.10025 s]
/proc/loadavg: 1.01 1.00 1.00 2/66 20213
/proc/meminfo: memFree=145732/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=2.58
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 767 27442 0 0 0 0 243 15 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017417360 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 2.58
Current children cumulated vsize (KiB) 9212

[startup+6.30032 s]
/proc/loadavg: 1.01 1.00 1.00 2/66 20214
/proc/meminfo: memFree=59404/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=2.58
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 767 27442 0 0 0 0 243 15 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017417360 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20214] ppid=20197 vsize=266264 CPUtime=3.55
/proc/20214/stat : 20214 (gringo) R 20197 20197 1745 0 -1 4202496 63247 0 0 0 336 19 0 0 20 0 1 0 120331251 272654336 54513 18446744073709551615 4194304 6531320 140735335280288 140735335277272 4452618 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20214/statm: 66566 54513 283 571 0 65987 0
Current children cumulated CPU time (s) 6.13
Current children cumulated vsize (KiB) 275476

[startup+12.7005 s]
/proc/loadavg: 1.01 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180664/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=5.22
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25735 0 0 0 515 7 0 0 20 0 1 0 120331722 90861568 21689 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21689 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.4
Current children cumulated vsize (KiB) 119984

[startup+25.5004 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180664/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=17.89
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 1782 7 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.07
Current children cumulated vsize (KiB) 119984

[startup+51.1004 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180664/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=43.24
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 4316 8 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4265984 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.42
Current children cumulated vsize (KiB) 119984

[startup+102.3 s]
/proc/loadavg: 1.03 1.01 1.00 2/67 20216
/proc/meminfo: memFree=180540/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=93.96
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 9386 10 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4687700 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.14
Current children cumulated vsize (KiB) 119984

[startup+162.3 s]
/proc/loadavg: 1.01 1.01 1.00 2/67 20216
/proc/meminfo: memFree=180540/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=153.37
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 15325 12 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.55
Current children cumulated vsize (KiB) 119984

[startup+222.304 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180540/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=212.86
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 21270 16 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.04
Current children cumulated vsize (KiB) 119984

[startup+282.3 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180540/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=272.41
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 27224 17 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4586347 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.59
Current children cumulated vsize (KiB) 119984

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

[startup+288 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180540/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=278.07
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 27790 17 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 285.25
Current children cumulated vsize (KiB) 119984

[startup+289.6 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180540/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=279.66
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 27948 18 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 286.84
Current children cumulated vsize (KiB) 119984

[startup+290.4 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180540/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=280.45
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 28027 18 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4407211 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 287.63
Current children cumulated vsize (KiB) 119984

[startup+291.2 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180540/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=281.24
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 28106 18 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4407084 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 288.42
Current children cumulated vsize (KiB) 119984

[startup+291.4 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180540/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=281.44
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 28126 18 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4407247 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 288.62
Current children cumulated vsize (KiB) 119984

[startup+291.5 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20216
/proc/meminfo: memFree=180540/1022884 swapFree=0/0
[pid=20197] ppid=20196 vsize=9212 CPUtime=7.17
/proc/20197/stat : 20197 (aspcud-full) S 20196 20197 1745 0 -1 4202496 808 101060 0 0 0 0 670 47 20 0 1 0 120330981 9433088 365 18446744073709551615 4194304 5129932 140734017418704 140734017416768 140019219608670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20197/statm: 2303 365 303 229 0 63 0
[pid=20215] ppid=20197 vsize=88732 CPUtime=281.54
/proc/20215/stat : 20215 (clasp) R 20197 20197 1745 0 -1 4202496 25806 0 0 0 28136 18 0 0 20 0 1 0 120331722 90861568 21760 18446744073709551615 4194304 6238623 140737066672304 140737066669328 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20215/statm: 22183 21760 263 500 0 21680 0
[pid=20216] ppid=20197 vsize=22040 CPUtime=0.01
/proc/20216/stat : 20216 (parse.py) S 20197 20197 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120331722 22568960 1128 18446744073709551615 4194304 6642060 140733802203808 140733802202168 140292635166496 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20216/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 288.72
Current children cumulated vsize (KiB) 119984

Child status: 0
Real time (s): 291.577
CPU time (s): 288.83
CPU user time (s): 288.122
CPU system time (s): 0.708044
CPU usage (%): 99.0581
Max. virtual memory (cumulated for all children) (KiB): 323288

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 288.122
system time used= 0.708044
maximum resident set size= 259520
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 129312
page faults= 0
swaps= 0
block input operations= 42376
block output operations= 31424
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 78
involuntary context switches= 33111

runsolver used 0.48803 second user time and 1.47209 second system time

The end