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/difficult/rand21.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand21.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/difficult/rand21.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.97 0.93 2/60 23280
/proc/meminfo: memFree=599988/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=3152 CPUtime=0
/proc/23280/stat : 23280 (runsolver) R 23279 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 41326631 3227648 33 18446744073709551615 134512640 134586868 4288553312 4288551360 4151415856 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.114248 s]
/proc/loadavg: 0.89 0.97 0.93 2/60 23280
/proc/meminfo: memFree=599988/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=0.06
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 732 3621 0 1 0 1 4 1 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209303472 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200334 s]
/proc/loadavg: 0.89 0.97 0.93 2/60 23280
/proc/meminfo: memFree=599988/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=0.06
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 732 3621 0 1 0 1 4 1 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209303472 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300316 s]
/proc/loadavg: 0.89 0.97 0.93 2/60 23280
/proc/meminfo: memFree=599988/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=0.06
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 732 3621 0 1 0 1 4 1 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209303472 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700232 s]
/proc/loadavg: 0.89 0.97 0.93 2/60 23280
/proc/meminfo: memFree=599988/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=0.06
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 732 3621 0 1 0 1 4 1 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209303472 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.89 0.97 0.93 2/62 23296
/proc/meminfo: memFree=565864/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=0.06
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 732 3621 0 1 0 1 4 1 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209303472 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23296] ppid=23280 vsize=48888 CPUtime=1.39
/proc/23296/stat : 23296 (cudf2lp) R 23280 23280 32685 0 -1 4202496 10868 0 0 0 131 8 0 0 20 0 1 0 41326638 50061312 9135 18446744073709551615 4194304 5690517 140736340950480 140736340946680 4363344 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/23296/statm: 12222 9135 160 366 0 11853 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 58100

[startup+3.10032 s]
/proc/loadavg: 0.89 0.97 0.93 2/62 23296
/proc/meminfo: memFree=533376/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=0.06
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 732 3621 0 1 0 1 4 1 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209303472 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23296] ppid=23280 vsize=93028 CPUtime=2.98
/proc/23296/stat : 23296 (cudf2lp) R 23280 23280 32685 0 -1 4202496 26552 0 0 0 286 12 0 0 20 0 1 0 41326638 95260672 19825 18446744073709551615 4194304 5690517 140736340950480 140736340948120 4960602 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/23296/statm: 23257 19825 160 366 0 22888 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 102240

[startup+6.30032 s]
/proc/loadavg: 0.89 0.97 0.93 2/62 23297
/proc/meminfo: memFree=543048/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=5.18
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 756 42944 0 1 0 1 490 27 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209303472 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23297] ppid=23280 vsize=29508 CPUtime=1.04
/proc/23297/stat : 23297 (gringo) R 23280 23280 32685 0 -1 4202496 7884 0 0 0 98 6 0 0 20 0 1 0 41327156 30216192 6773 18446744073709551615 4194304 6531320 140736467394992 140736467391608 5506464 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23297/statm: 7377 6773 259 571 0 6798 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 38720

[startup+12.7003 s]
/proc/loadavg: 0.90 0.97 0.93 2/62 23297
/proc/meminfo: memFree=241976/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=5.18
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 756 42944 0 1 0 1 490 27 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209303472 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23297] ppid=23280 vsize=437784 CPUtime=7.38
/proc/23297/stat : 23297 (gringo) R 23280 23280 32685 0 -1 4202496 104109 0 0 0 686 52 0 0 20 0 1 0 41327156 448290816 87634 18446744073709551615 4194304 6531320 140736467394992 140736467391608 4331256 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23297/statm: 109446 87634 282 571 0 108867 0
Current children cumulated CPU time (s) 12.56
Current children cumulated vsize (KiB) 446996

[startup+25.5004 s]
/proc/loadavg: 0.92 0.97 0.93 2/63 23299
/proc/meminfo: memFree=420136/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=18.12
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 793 222233 0 1 0 1 1683 128 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209302880 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23298] ppid=23280 vsize=238036 CPUtime=6.67
/proc/23298/stat : 23298 (clasp) R 23280 23280 32685 0 -1 4202496 71378 0 1 0 640 27 0 0 20 0 1 0 41328500 243748864 58249 18446744073709551615 4194304 6238623 140735619461888 140735619458912 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/23298/statm: 59509 58249 263 500 0 59006 0
[pid=23299] ppid=23280 vsize=22040 CPUtime=0.01
/proc/23299/stat : 23299 (parse.py) S 23280 23280 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 41328500 22568960 1128 18446744073709551615 4194304 6642060 140737042464128 140737042462488 140015369119520 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/23299/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.8
Current children cumulated vsize (KiB) 269288

[startup+51.1004 s]
/proc/loadavg: 0.95 0.97 0.93 2/63 23299
/proc/meminfo: memFree=417160/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=18.12
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 793 222233 0 1 0 1 1683 128 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209302880 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23298] ppid=23280 vsize=238036 CPUtime=32.07
/proc/23298/stat : 23298 (clasp) R 23280 23280 32685 0 -1 4202496 72224 0 1 0 3180 27 0 0 20 0 1 0 41328500 243748864 59095 18446744073709551615 4194304 6238623 140735619461888 140735619458912 4295374 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/23298/statm: 59509 59095 264 500 0 59006 0
[pid=23299] ppid=23280 vsize=22040 CPUtime=0.01
/proc/23299/stat : 23299 (parse.py) S 23280 23280 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 41328500 22568960 1128 18446744073709551615 4194304 6642060 140737042464128 140737042462488 140015369119520 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/23299/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.2
Current children cumulated vsize (KiB) 269288

[startup+102.3 s]
/proc/loadavg: 1.04 0.99 0.94 2/63 23307
/proc/meminfo: memFree=415796/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=18.12
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 793 222233 0 1 0 1 1683 128 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209302880 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23298] ppid=23280 vsize=238036 CPUtime=82.84
/proc/23298/stat : 23298 (clasp) R 23280 23280 32685 0 -1 4202496 72224 0 1 0 8257 27 0 0 20 0 1 0 41328500 243748864 59095 18446744073709551615 4194304 6238623 140735619461888 140735619458912 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/23298/statm: 59509 59095 264 500 0 59006 0
[pid=23299] ppid=23280 vsize=22040 CPUtime=0.01
/proc/23299/stat : 23299 (parse.py) S 23280 23280 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 41328500 22568960 1128 18446744073709551615 4194304 6642060 140737042464128 140737042462488 140015369119520 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/23299/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 100.97
Current children cumulated vsize (KiB) 269288

[startup+162.3 s]
/proc/loadavg: 1.07 1.00 0.94 2/59 23419
/proc/meminfo: memFree=348992/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=18.12
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 793 222233 0 1 0 1 1683 128 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209302880 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23298] ppid=23280 vsize=283412 CPUtime=139.63
/proc/23298/stat : 23298 (clasp) R 23280 23280 32685 0 -1 4202496 83625 0 1 0 13932 31 0 0 20 0 1 0 41328500 290213888 70496 18446744073709551615 4194304 6238623 140735619461888 140735619458440 4333050 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/23298/statm: 70853 70496 264 500 0 70350 0
[pid=23299] ppid=23280 vsize=22040 CPUtime=0.01
/proc/23299/stat : 23299 (parse.py) S 23280 23280 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 41328500 22568960 1128 18446744073709551615 4194304 6642060 140737042464128 140737042462488 140015369119520 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/23299/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 157.76
Current children cumulated vsize (KiB) 314664

[startup+222.305 s]
/proc/loadavg: 1.02 1.00 0.94 2/59 23419
/proc/meminfo: memFree=292200/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=18.12
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 793 222233 0 1 0 1 1683 128 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209302880 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23298] ppid=23280 vsize=335152 CPUtime=199.27
/proc/23298/stat : 23298 (clasp) R 23280 23280 32685 0 -1 4202496 96526 0 1 0 19889 38 0 0 20 0 1 0 41328500 343195648 83396 18446744073709551615 4194304 6238623 140735619461888 140735619458440 4687693 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/23298/statm: 83788 83396 264 500 0 83285 0
[pid=23299] ppid=23280 vsize=22040 CPUtime=0.01
/proc/23299/stat : 23299 (parse.py) S 23280 23280 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 41328500 22568960 1128 18446744073709551615 4194304 6642060 140737042464128 140737042462488 140015369119520 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/23299/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 217.4
Current children cumulated vsize (KiB) 366404

[startup+282.3 s]
/proc/loadavg: 1.01 1.00 0.94 2/59 23419
/proc/meminfo: memFree=287612/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=18.12
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 793 222233 0 1 0 1 1683 128 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209302880 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23298] ppid=23280 vsize=339844 CPUtime=258.9
/proc/23298/stat : 23298 (clasp) R 23280 23280 32685 0 -1 4202496 97689 0 1 0 25852 38 0 0 20 0 1 0 41328500 348000256 84559 18446744073709551615 4194304 6238623 140735619461888 140735619458440 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/23298/statm: 84961 84559 264 500 0 84458 0
[pid=23299] ppid=23280 vsize=22040 CPUtime=0.01
/proc/23299/stat : 23299 (parse.py) S 23280 23280 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 41328500 22568960 1128 18446744073709551615 4194304 6642060 140737042464128 140737042462488 140015369119520 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/23299/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 277.03
Current children cumulated vsize (KiB) 371096



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+305.4 s]
/proc/loadavg: 1.00 1.00 0.94 2/59 23419
/proc/meminfo: memFree=287488/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=18.12
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 793 222233 0 1 0 1 1683 128 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209302880 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23298] ppid=23280 vsize=339844 CPUtime=281.88
/proc/23298/stat : 23298 (clasp) R 23280 23280 32685 0 -1 4202496 97689 0 1 0 28150 38 0 0 20 0 1 0 41328500 348000256 84559 18446744073709551615 4194304 6238623 140735619461888 140735619458440 4306751 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/23298/statm: 84961 84559 264 500 0 84458 0
[pid=23299] ppid=23280 vsize=22040 CPUtime=0.01
/proc/23299/stat : 23299 (parse.py) S 23280 23280 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 41328500 22568960 1128 18446744073709551615 4194304 6642060 140737042464128 140737042462488 140015369119520 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/23299/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.01
Current children cumulated vsize (KiB) 371096

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

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

[startup+305.4 s]
/proc/loadavg: 1.00 1.00 0.94 2/59 23419
/proc/meminfo: memFree=287488/1022884 swapFree=0/0
[pid=23280] ppid=23279 vsize=9212 CPUtime=18.12
/proc/23280/stat : 23280 (aspcud-full) S 23279 23280 32685 0 -1 4202496 793 222233 0 1 0 1 1683 128 20 0 1 0 41326631 9433088 364 18446744073709551615 4194304 5129932 140733209304816 140733209302880 139982588810334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23280/statm: 2303 364 303 229 0 63 0
[pid=23298] ppid=23280 vsize=339844 CPUtime=281.88
/proc/23298/stat : 23298 (clasp) R 23280 23280 32685 0 -1 4202496 97689 0 1 0 28150 38 0 0 20 0 1 0 41328500 348000256 84559 18446744073709551615 4194304 6238623 140735619461888 140735619458440 4306751 0 0 16781316 18946 0 0 0 17 0 0 0 6 0 0
/proc/23298/statm: 84961 84559 264 500 0 84458 0
[pid=23299] ppid=23280 vsize=22040 CPUtime=0.01
/proc/23299/stat : 23299 (parse.py) S 23280 23280 32685 0 -1 4202496 1308 0 10 0 1 0 0 0 20 0 1 0 41328500 22568960 1128 18446744073709551615 4194304 6642060 140737042464128 140737042462488 140015369119520 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/23299/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.01
Current children cumulated vsize (KiB) 371096

Child status: 0
Real time (s): 305.456
CPU time (s): 300.103
CPU user time (s): 298.371
CPU system time (s): 1.73211
CPU usage (%): 98.2475
Max. virtual memory (cumulated for all children) (KiB): 783908

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.371
system time used= 1.73211
maximum resident set size= 651240
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 322347
page faults= 12
swaps= 0
block input operations= 80960
block output operations= 82352
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 106
involuntary context switches= 5470

runsolver used 0.696043 second user time and 1.32808 second system time

The end