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/upgrade/install/rand220.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand220.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/upgrade/install/rand220.cudf.result -count(down),-notuptodate(solution),-aligned(solution,source,sourceversion),-unsat_recommends(solution),-count(new) 

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: 0.00 0.00 0.00 2/59 26123
/proc/meminfo: memFree=68636/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=3152 CPUtime=0
/proc/26123/stat : 26123 (runsolver) R 26122 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117040316 3227648 32 18446744073709551615 134512640 134586868 4291330432 4291328480 4151956528 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.154368 s]
/proc/loadavg: 0.00 0.00 0.00 2/59 26123
/proc/meminfo: memFree=68636/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=0.03
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 733 3621 0 3 0 0 2 1 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711738080 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200258 s]
/proc/loadavg: 0.00 0.00 0.00 2/59 26123
/proc/meminfo: memFree=68636/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=0.03
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 733 3621 0 3 0 0 2 1 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711738080 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/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.00 0.00 0.00 2/59 26123
/proc/meminfo: memFree=68636/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=0.03
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 733 3621 0 3 0 0 2 1 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711738080 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700344 s]
/proc/loadavg: 0.00 0.00 0.00 2/59 26123
/proc/meminfo: memFree=68636/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=0.03
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 733 3621 0 3 0 0 2 1 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711738080 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50037 s]
/proc/loadavg: 0.00 0.00 0.00 2/61 26139
/proc/meminfo: memFree=32496/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=0.03
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 733 3621 0 3 0 0 2 1 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711738080 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26139] ppid=26123 vsize=58176 CPUtime=1.16
/proc/26139/stat : 26139 (cudf2lp) R 26123 26123 1733 0 -1 4202496 14088 0 0 0 112 4 0 0 20 0 1 0 117040324 59572224 12355 18446744073709551615 4194304 5690517 140733460276224 140733460272376 4963881 0 0 16781316 0 0 0 0 17 0 0 0 23 0 0
/proc/26139/statm: 14544 12355 160 366 0 14175 0
Current children cumulated CPU time (s) 1.19
Current children cumulated vsize (KiB) 67388

[startup+3.10031 s]
/proc/loadavg: 0.00 0.00 0.00 1/61 26139
/proc/meminfo: memFree=9428/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=0.03
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 733 3621 0 3 0 0 2 1 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711738080 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26139] ppid=26123 vsize=112464 CPUtime=2.4
/proc/26139/stat : 26139 (cudf2lp) R 26123 26123 1733 0 -1 4202496 27931 0 0 0 230 10 0 0 20 0 1 0 117040324 115163136 24533 18446744073709551615 4194304 5690517 140733460276224 140733460272376 4970406 0 0 16781316 0 0 0 0 17 0 0 0 58 0 0
/proc/26139/statm: 28116 24533 160 366 0 27747 0
Current children cumulated CPU time (s) 2.43
Current children cumulated vsize (KiB) 121676
heavy processes:

[startup+6.3003 s]
/proc/loadavg: 0.08 0.02 0.01 2/62 26141
/proc/meminfo: memFree=128336/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=4.61
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 759 44900 0 3 0 0 439 22 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711738080 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26141] ppid=26123 vsize=24552 CPUtime=0.87
/proc/26141/stat : 26141 (gringo) R 26123 26123 1733 0 -1 4202496 6862 0 0 0 83 4 0 0 20 0 1 0 117040858 25141248 5267 18446744073709551615 4194304 6531320 140737125575568 140737125572184 4359010 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/26141/statm: 6138 5267 259 571 0 5559 0
Current children cumulated CPU time (s) 5.48
Current children cumulated vsize (KiB) 33764

[startup+12.7003 s]
/proc/loadavg: 0.15 0.03 0.01 2/62 26141
/proc/meminfo: memFree=9740/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=4.61
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 759 44900 0 3 0 0 439 22 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711738080 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26141] ppid=26123 vsize=392076 CPUtime=7.06
/proc/26141/stat : 26141 (gringo) R 26123 26123 1733 0 -1 4202496 93694 0 0 0 668 38 0 0 20 0 1 0 117040858 401485824 83390 18446744073709551615 4194304 6531320 140737125575568 140737125571912 4595619 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/26141/statm: 98019 83390 282 571 0 97440 0
Current children cumulated CPU time (s) 11.67
Current children cumulated vsize (KiB) 401288

[startup+25.5004 s]
/proc/loadavg: 0.34 0.08 0.02 2/63 26143
/proc/meminfo: memFree=321664/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=10.02
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 990 12 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4295427 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.05
Current children cumulated vsize (KiB) 197256

[startup+51.1003 s]
/proc/loadavg: 0.56 0.15 0.05 2/63 26143
/proc/meminfo: memFree=321664/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=35.41
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 3529 12 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 49.44
Current children cumulated vsize (KiB) 197256

[startup+102.3 s]
/proc/loadavg: 0.85 0.29 0.10 2/63 26143
/proc/meminfo: memFree=321664/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=86.2
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 8608 12 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 100.23
Current children cumulated vsize (KiB) 197256

[startup+162.3 s]
/proc/loadavg: 1.02 0.44 0.16 2/63 26143
/proc/meminfo: memFree=321664/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=145.74
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 14561 13 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4677133 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 159.77
Current children cumulated vsize (KiB) 197256

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

[startup+166.4 s]
/proc/loadavg: 1.02 0.45 0.16 2/63 26143
/proc/meminfo: memFree=321540/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=149.81
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 14968 13 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 163.84
Current children cumulated vsize (KiB) 197256

[startup+179.2 s]
/proc/loadavg: 1.02 0.47 0.18 2/63 26143
/proc/meminfo: memFree=321540/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=162.51
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 16238 13 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4635586 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 176.54
Current children cumulated vsize (KiB) 197256

[startup+182.4 s]
/proc/loadavg: 1.02 0.47 0.18 2/63 26143
/proc/meminfo: memFree=321540/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=165.68
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 16555 13 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4635208 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 179.71
Current children cumulated vsize (KiB) 197256

[startup+185.6 s]
/proc/loadavg: 1.01 0.48 0.18 2/63 26143
/proc/meminfo: memFree=321540/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=168.86
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 16873 13 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 182.89
Current children cumulated vsize (KiB) 197256

[startup+186.4 s]
/proc/loadavg: 1.01 0.48 0.18 2/63 26143
/proc/meminfo: memFree=321540/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=169.65
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 16952 13 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4371540 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 183.68
Current children cumulated vsize (KiB) 197256

[startup+187.2 s]
/proc/loadavg: 1.01 0.48 0.18 2/63 26143
/proc/meminfo: memFree=321540/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=170.44
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 17031 13 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 184.47
Current children cumulated vsize (KiB) 197256

[startup+187.6 s]
/proc/loadavg: 1.01 0.48 0.18 2/63 26143
/proc/meminfo: memFree=321540/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=170.84
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49239 0 22 0 17071 13 0 0 20 0 1 0 117041834 169988096 40700 18446744073709551615 4194304 6238623 140733205338864 140733205335888 4656436 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 40700 264 500 0 40998 0
[pid=26143] ppid=26123 vsize=22040 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1302 0 16 0 0 1 0 0 20 0 1 0 117041834 22568960 1128 18446744073709551615 4194304 6642060 140736591064560 140736591062920 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 184.87
Current children cumulated vsize (KiB) 197256

[startup+187.701 s]
/proc/loadavg: 1.01 0.48 0.18 2/63 26143
/proc/meminfo: memFree=321540/1022884 swapFree=0/0
[pid=26123] ppid=26122 vsize=9212 CPUtime=14.02
/proc/26123/stat : 26123 (aspcud-full) S 26122 26123 1733 0 -1 4202496 799 183321 0 3 0 0 1314 88 20 0 1 0 117040316 9433088 364 18446744073709551615 4194304 5129932 140735711739424 140735711737488 140126622241886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26123/statm: 2303 364 303 229 0 63 0
[pid=26142] ppid=26123 vsize=166004 CPUtime=170.93
/proc/26142/stat : 26142 (clasp) R 26123 26123 1733 0 -1 4202496 49249 0 22 0 17079 14 0 0 20 0 1 0 117041834 169988096 28422 18446744073709551615 4194304 6238623 140733205338864 140733205338392 5666714 0 0 16781316 18946 0 0 0 17 0 0 0 19 0 0
/proc/26142/statm: 41501 28422 274 500 0 40998 0
[pid=26143] ppid=26123 vsize=22044 CPUtime=0.01
/proc/26143/stat : 26143 (parse.py) S 26123 26123 1733 0 -1 4202496 1304 0 16 0 0 1 0 0 20 0 1 0 117041834 22573056 1130 18446744073709551615 4194304 6642060 140736591064560 140736591062840 140715538773792 0 0 16777220 20994 0 0 0 17 0 0 0 59 0 0
/proc/26143/statm: 5511 1130 508 598 0 597 0
Current children cumulated CPU time (s) 184.96
Current children cumulated vsize (KiB) 197260

Child status: 0
Real time (s): 187.769
CPU time (s): 185.052
CPU user time (s): 183.952
CPU system time (s): 1.10007
CPU usage (%): 98.5527
Max. virtual memory (cumulated for all children) (KiB): 597376

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 183.951
system time used= 1.10007
maximum resident set size= 479680
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 234965
page faults= 42
swaps= 0
block input operations= 75064
block output operations= 66608
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 224
involuntary context switches= 21610

runsolver used 0.344021 second user time and 0.708044 second system time

The end