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/install/rand220.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand220.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/paranoid-size/install/rand220.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: 0.00 0.01 0.10 2/60 3165
/proc/meminfo: memFree=34716/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=3152 CPUtime=0
/proc/3165/stat : 3165 (runsolver) R 3164 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115118272 3227648 32 18446744073709551615 134512640 134586868 4293573632 4293571680 4151653424 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.201769 s]
/proc/loadavg: 0.00 0.01 0.10 2/60 3165
/proc/meminfo: memFree=34716/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=0.03
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 736 3610 1 3 0 0 2 1 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534897136 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300313 s]
/proc/loadavg: 0.00 0.01 0.10 2/60 3165
/proc/meminfo: memFree=34716/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=0.03
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 736 3610 1 3 0 0 2 1 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534897136 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.4003 s]
/proc/loadavg: 0.00 0.01 0.10 2/60 3165
/proc/meminfo: memFree=34716/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=0.03
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 736 3610 1 3 0 0 2 1 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534897136 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700215 s]
/proc/loadavg: 0.00 0.01 0.10 2/60 3165
/proc/meminfo: memFree=34716/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=0.03
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 736 3610 1 3 0 0 2 1 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534897136 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 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: 0.00 0.01 0.10 2/62 3181
/proc/meminfo: memFree=10048/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=0.03
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 736 3610 1 3 0 0 2 1 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534897136 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
[pid=3181] ppid=3165 vsize=33064 CPUtime=1.35
/proc/3181/stat : 3181 (cudf2lp) R 3165 3165 1750 0 -1 4202496 9603 0 0 0 132 3 0 0 20 0 1 0 115118281 33857536 7869 18446744073709551615 4194304 5690517 140736662936048 140736662933416 4293191 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/3181/statm: 8266 7869 160 366 0 7897 0
Current children cumulated CPU time (s) 1.38
Current children cumulated vsize (KiB) 42276

[startup+3.1003 s]
/proc/loadavg: 0.00 0.01 0.10 2/62 3181
/proc/meminfo: memFree=10168/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=0.03
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 736 3610 1 3 0 0 2 1 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534897136 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
[pid=3181] ppid=3165 vsize=93028 CPUtime=2.91
/proc/3181/stat : 3181 (cudf2lp) R 3165 3165 1750 0 -1 4202496 26591 0 0 0 277 14 0 0 20 0 1 0 115118281 95260672 19863 18446744073709551615 4194304 5690517 140736662936048 140736662933688 4970533 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/3181/statm: 23257 19863 160 366 0 22888 0
Current children cumulated CPU time (s) 2.94
Current children cumulated vsize (KiB) 102240

[startup+6.3003 s]
/proc/loadavg: 0.08 0.03 0.10 2/62 3182
/proc/meminfo: memFree=110980/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=4.75
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 762 42931 1 3 0 0 448 27 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534897136 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
[pid=3182] ppid=3165 vsize=39480 CPUtime=1.32
/proc/3182/stat : 3182 (gringo) R 3165 3165 1750 0 -1 4202496 10979 0 0 0 128 4 0 0 20 0 1 0 115118768 40427520 7845 18446744073709551615 4194304 6531320 140736759337968 140736759333768 4330265 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/3182/statm: 9870 7845 259 571 0 9291 0
Current children cumulated CPU time (s) 6.07
Current children cumulated vsize (KiB) 48692

[startup+12.7004 s]
/proc/loadavg: 0.16 0.05 0.11 2/63 3184
/proc/meminfo: memFree=295328/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=11.07
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 803 149644 1 3 0 0 1031 76 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534896544 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
[pid=3183] ppid=3165 vsize=138428 CPUtime=0.98
/proc/3183/stat : 3183 (clasp) R 3165 3165 1750 0 -1 4202496 37974 0 22 0 82 16 0 0 20 0 1 0 115119419 141750272 33810 18446744073709551615 4194304 6238623 140737094152288 140737094149624 4494854 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/3183/statm: 34607 33810 215 500 0 34104 0
[pid=3184] ppid=3165 vsize=22040 CPUtime=0.02
/proc/3184/stat : 3184 (parse.py) S 3165 3165 1750 0 -1 4202496 1303 0 15 0 2 0 0 0 20 0 1 0 115119419 22568960 1127 18446744073709551615 4194304 6642060 140735777662976 140735777661336 140469847398176 0 0 16777220 20994 0 0 0 17 0 0 0 22 0 0
/proc/3184/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.07
Current children cumulated vsize (KiB) 169680

[startup+25.509 s]
/proc/loadavg: 0.34 0.09 0.12 2/63 3184
/proc/meminfo: memFree=257756/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=11.07
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 803 149644 1 3 0 0 1031 76 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534896544 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
[pid=3183] ppid=3165 vsize=138296 CPUtime=13.67
/proc/3183/stat : 3183 (clasp) R 3165 3165 1750 0 -1 4202496 40386 0 22 0 1349 18 0 0 20 0 1 0 115119419 141615104 34246 18446744073709551615 4194304 6238623 140737094152288 140737094149312 4684893 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/3183/statm: 34574 34246 264 500 0 34071 0
[pid=3184] ppid=3165 vsize=22040 CPUtime=0.02
/proc/3184/stat : 3184 (parse.py) S 3165 3165 1750 0 -1 4202496 1303 0 15 0 2 0 0 0 20 0 1 0 115119419 22568960 1127 18446744073709551615 4194304 6642060 140735777662976 140735777661336 140469847398176 0 0 16777220 20994 0 0 0 17 0 0 0 22 0 0
/proc/3184/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 24.76
Current children cumulated vsize (KiB) 169548

[startup+51.1004 s]
/proc/loadavg: 0.57 0.16 0.14 2/63 3184
/proc/meminfo: memFree=257756/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=11.07
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 803 149644 1 3 0 0 1031 76 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534896544 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
[pid=3183] ppid=3165 vsize=138296 CPUtime=39.01
/proc/3183/stat : 3183 (clasp) R 3165 3165 1750 0 -1 4202496 40386 0 22 0 3883 18 0 0 20 0 1 0 115119419 141615104 34246 18446744073709551615 4194304 6238623 140737094152288 140737094149312 4676877 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/3183/statm: 34574 34246 264 500 0 34071 0
[pid=3184] ppid=3165 vsize=22040 CPUtime=0.02
/proc/3184/stat : 3184 (parse.py) S 3165 3165 1750 0 -1 4202496 1303 0 15 0 2 0 0 0 20 0 1 0 115119419 22568960 1127 18446744073709551615 4194304 6642060 140735777662976 140735777661336 140469847398176 0 0 16777220 20994 0 0 0 17 0 0 0 22 0 0
/proc/3184/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.1
Current children cumulated vsize (KiB) 169548

[startup+102.3 s]
/proc/loadavg: 0.81 0.29 0.19 2/63 3184
/proc/meminfo: memFree=239528/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=11.07
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 803 149644 1 3 0 0 1031 76 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534896544 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
[pid=3183] ppid=3165 vsize=156388 CPUtime=89.71
/proc/3183/stat : 3183 (clasp) R 3165 3165 1750 0 -1 4202496 44898 0 22 0 8949 22 0 0 20 0 1 0 115119419 160141312 38758 18446744073709551615 4194304 6238623 140737094152288 140737094148840 4413046 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/3183/statm: 39097 38758 264 500 0 38594 0
[pid=3184] ppid=3165 vsize=22040 CPUtime=0.02
/proc/3184/stat : 3184 (parse.py) S 3165 3165 1750 0 -1 4202496 1303 0 15 0 2 0 0 0 20 0 1 0 115119419 22568960 1127 18446744073709551615 4194304 6642060 140735777662976 140735777661336 140469847398176 0 0 16777220 20994 0 0 0 17 0 0 0 22 0 0
/proc/3184/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 100.8
Current children cumulated vsize (KiB) 187640



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+152.003 s]
/proc/loadavg: 0.92 0.40 0.22 2/63 3184
/proc/meminfo: memFree=223780/1022884 swapFree=0/0
[pid=3165] ppid=3164 vsize=9212 CPUtime=11.07
/proc/3165/stat : 3165 (aspcud-basic) S 3164 3165 1750 0 -1 4202496 803 149644 1 3 0 0 1031 76 20 0 1 0 115118272 9433088 364 18446744073709551615 4194304 5129932 140733534898480 140733534896544 140536095454302 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/3165/statm: 2303 364 303 229 0 63 0
[pid=3183] ppid=3165 vsize=172248 CPUtime=138.93
/proc/3183/stat : 3183 (clasp) R 3165 3165 1750 0 -1 4202496 48834 0 22 0 13868 25 0 0 20 0 1 0 115119419 176381952 42694 18446744073709551615 4194304 6238623 140737094152288 140737094148840 4676760 0 0 16781316 18946 0 0 0 17 0 0 0 21 0 0
/proc/3183/statm: 43062 42694 264 500 0 42559 0
[pid=3184] ppid=3165 vsize=22040 CPUtime=0.02
/proc/3184/stat : 3184 (parse.py) S 3165 3165 1750 0 -1 4202496 1303 0 15 0 2 0 0 0 20 0 1 0 115119419 22568960 1127 18446744073709551615 4194304 6642060 140735777662976 140735777661336 140469847398176 0 0 16777220 20994 0 0 0 17 0 0 0 22 0 0
/proc/3184/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 150.02
Current children cumulated vsize (KiB) 203500

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 152.056
CPU time (s): 150.077
CPU user time (s): 149.025
CPU system time (s): 1.05206
CPU usage (%): 98.6986
Max. virtual memory (cumulated for all children) (KiB): 456636

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.025
system time used= 1.05207
maximum resident set size= 389716
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 200896
page faults= 43
swaps= 0
block input operations= 74168
block output operations= 50056
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 137
involuntary context switches= 17461

runsolver used 0.432027 second user time and 0.716044 second system time

The end