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/trendy-size/upgrade/easy/rand381.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand381.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/easy/rand381.cudf.result -count(removed),-sum(solution,installedsize),-notuptodate(solution),-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.89 0.95 0.98 2/59 1286
/proc/meminfo: memFree=428000/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=3152 CPUtime=0
/proc/1286/stat : 1286 (runsolver) R 1285 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119348475 3227648 32 18446744073709551615 134512640 134586868 4287876864 4287874912 4152013872 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/1286/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.183477 s]
/proc/loadavg: 0.89 0.95 0.98 2/59 1286
/proc/meminfo: memFree=428000/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=0.05
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 732 3616 2 7 0 0 3 2 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457920 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200318 s]
/proc/loadavg: 0.89 0.95 0.98 2/59 1286
/proc/meminfo: memFree=428000/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=0.05
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 732 3616 2 7 0 0 3 2 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457920 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300311 s]
/proc/loadavg: 0.89 0.95 0.98 2/59 1286
/proc/meminfo: memFree=428000/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=0.05
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 732 3616 2 7 0 0 3 2 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457920 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700224 s]
/proc/loadavg: 0.89 0.95 0.98 2/59 1286
/proc/meminfo: memFree=428000/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=0.05
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 732 3616 2 7 0 0 3 2 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457920 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.89 0.95 0.98 2/61 1302
/proc/meminfo: memFree=394380/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=0.05
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 732 3616 2 7 0 0 3 2 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457920 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1302] ppid=1286 vsize=49452 CPUtime=1.36
/proc/1302/stat : 1302 (cudf2lp) R 1286 1286 1733 0 -1 4202496 11356 0 0 0 132 4 0 0 20 0 1 0 119348485 50638848 9623 18446744073709551615 4194304 5690517 140735778391408 140735778387576 4363476 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/1302/statm: 12363 9623 159 366 0 11994 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 58664

[startup+3.10033 s]
/proc/loadavg: 0.89 0.95 0.98 2/61 1302
/proc/meminfo: memFree=363628/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=0.05
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 732 3616 2 7 0 0 3 2 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457920 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1302] ppid=1286 vsize=72092 CPUtime=2.95
/proc/1302/stat : 1302 (cudf2lp) R 1286 1286 1733 0 -1 4202496 23821 0 0 0 281 14 0 0 20 0 1 0 119348485 73822208 17758 18446744073709551615 4194304 5690517 140735778391408 140735778388744 4956989 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/1302/statm: 18023 17758 174 366 0 17654 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 81304

[startup+6.30032 s]
/proc/loadavg: 0.90 0.96 0.98 2/61 1303
/proc/meminfo: memFree=307952/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=3.12
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 758 27439 2 7 0 0 294 18 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457920 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1303] ppid=1286 vsize=151796 CPUtime=3.04
/proc/1303/stat : 1303 (gringo) R 1286 1286 1733 0 -1 4202496 38527 0 0 0 284 20 0 0 20 0 1 0 119348797 155439104 34085 18446744073709551615 4194304 6531320 140735683851088 140735683847016 4597961 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/1303/statm: 37949 34085 281 571 0 37370 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 161008

[startup+12.7004 s]
/proc/loadavg: 0.91 0.96 0.98 2/62 1305
/proc/meminfo: memFree=268148/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=138176 CPUtime=1.91
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 40154 0 0 0 180 11 0 0 20 0 1 0 119349548 141492224 33996 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 34544 33996 263 500 0 34041 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 169428

[startup+25.5004 s]
/proc/loadavg: 0.93 0.96 0.98 2/62 1305
/proc/meminfo: memFree=267900/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=138176 CPUtime=14.59
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 40265 0 0 0 1447 12 0 0 20 0 1 0 119349548 141492224 34107 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4407011 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 34544 34107 264 500 0 34041 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.12
Current children cumulated vsize (KiB) 169428

[startup+51.1003 s]
/proc/loadavg: 0.95 0.96 0.98 2/62 1305
/proc/meminfo: memFree=267156/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=138176 CPUtime=39.95
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 40396 0 0 0 3982 13 0 0 20 0 1 0 119349548 141492224 34238 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4407247 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 34544 34238 264 500 0 34041 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.48
Current children cumulated vsize (KiB) 169428

[startup+102.3 s]
/proc/loadavg: 0.98 0.96 0.98 2/62 1305
/proc/meminfo: memFree=267156/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=138176 CPUtime=90.78
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 40396 0 0 0 9064 14 0 0 20 0 1 0 119349548 141492224 34238 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 34544 34238 264 500 0 34041 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.31
Current children cumulated vsize (KiB) 169428

[startup+162.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1305
/proc/meminfo: memFree=227476/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=177820 CPUtime=150.33
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 50274 0 0 0 15010 23 0 0 20 0 1 0 119349548 182087680 44116 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4407011 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 44455 44116 264 500 0 43952 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.86
Current children cumulated vsize (KiB) 209072

[startup+222.303 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1305
/proc/meminfo: memFree=179736/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=225264 CPUtime=209.89
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 62162 0 0 0 20962 27 0 0 20 0 1 0 119349548 230670336 56004 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 56316 56004 264 500 0 55813 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 220.42
Current children cumulated vsize (KiB) 256516

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1305
/proc/meminfo: memFree=158036/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=247092 CPUtime=269.45
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 67585 0 0 0 26915 30 0 0 20 0 1 0 119349548 253022208 61427 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 61773 61427 264 500 0 61270 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 279.98
Current children cumulated vsize (KiB) 278344

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

[startup+294.4 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1305
/proc/meminfo: memFree=158036/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=247092 CPUtime=281.46
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 67585 0 0 0 28116 30 0 0 20 0 1 0 119349548 253022208 61427 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4687707 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 61773 61427 264 500 0 61270 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 291.99
Current children cumulated vsize (KiB) 278344

[startup+297.6 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1305
/proc/meminfo: memFree=158036/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=247092 CPUtime=284.63
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 67585 0 0 0 28433 30 0 0 20 0 1 0 119349548 253022208 61427 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4407084 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 61773 61427 264 500 0 61270 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 295.16
Current children cumulated vsize (KiB) 278344

[startup+300.8 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1305
/proc/meminfo: memFree=158036/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=247092 CPUtime=287.81
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 67585 0 0 0 28751 30 0 0 20 0 1 0 119349548 253022208 61427 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4407165 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 61773 61427 264 500 0 61270 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 298.34
Current children cumulated vsize (KiB) 278344

[startup+301.6 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1305
/proc/meminfo: memFree=158036/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=247092 CPUtime=288.61
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 67585 0 0 0 28831 30 0 0 20 0 1 0 119349548 253022208 61427 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 61773 61427 264 500 0 61270 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 299.14
Current children cumulated vsize (KiB) 278344

[startup+302 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1305
/proc/meminfo: memFree=158036/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=247092 CPUtime=289
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 67585 0 0 0 28870 30 0 0 20 0 1 0 119349548 253022208 61427 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4676715 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 61773 61427 264 500 0 61270 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 299.53
Current children cumulated vsize (KiB) 278344

[startup+302.2 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1305
/proc/meminfo: memFree=158036/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=247092 CPUtime=289.2
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 67585 0 0 0 28890 30 0 0 20 0 1 0 119349548 253022208 61427 18446744073709551615 4194304 6238623 140733404385888 140733404382912 4307197 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 61773 61427 264 500 0 61270 0
[pid=1305] ppid=1286 vsize=22040 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1317 0 0 0 0 2 0 0 20 0 1 0 119349548 22568960 1127 18446744073709551615 4194304 6642060 140733740730240 140733740728600 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 299.73
Current children cumulated vsize (KiB) 278344

[startup+302.301 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 1305
/proc/meminfo: memFree=158036/1022884 swapFree=0/0
[pid=1286] ppid=1285 vsize=9212 CPUtime=10.51
/proc/1286/stat : 1286 (aspcud-full) S 1285 1286 1733 0 -1 4202496 798 135152 2 7 0 0 974 77 20 0 1 0 119348475 9433088 365 18446744073709551615 4194304 5129932 140733616459264 140733616457328 140518432805982 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/1286/statm: 2303 365 303 229 0 63 0
[pid=1304] ppid=1286 vsize=247092 CPUtime=289.3
/proc/1304/stat : 1304 (clasp) R 1286 1286 1733 0 -1 4202496 67595 0 0 0 28898 32 0 0 20 0 1 0 119349548 253022208 37885 18446744073709551615 4194304 6238623 140733404385888 140733404385368 5666714 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/1304/statm: 61773 37885 274 500 0 61270 0
[pid=1305] ppid=1286 vsize=22044 CPUtime=0.02
/proc/1305/stat : 1305 (parse.py) S 1286 1286 1733 0 -1 4202496 1321 0 0 0 0 2 0 0 20 0 1 0 119349548 22573056 1131 18446744073709551615 4194304 6642060 140733740730240 140733740728440 139746431129376 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/1305/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 299.83
Current children cumulated vsize (KiB) 278348

Child status: 0
Real time (s): 302.354
CPU time (s): 299.927
CPU user time (s): 298.751
CPU system time (s): 1.17607
CPU usage (%): 99.1973
Max. virtual memory (cumulated for all children) (KiB): 456636

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.751
system time used= 1.17607
maximum resident set size= 396680
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 205170
page faults= 9
swaps= 0
block input operations= 42904
block output operations= 46736
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 84
involuntary context switches= 34203

runsolver used 0.708044 second user time and 0.97206 second system time

The end