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/difficult/rand752.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand752.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/difficult/rand752.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.90 0.97 0.98 2/59 4974
/proc/meminfo: memFree=332852/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=3152 CPUtime=0
/proc/4974/stat : 4974 (runsolver) R 4973 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120419426 3227648 32 18446744073709551615 134512640 134586868 4289190752 4289188800 4152116272 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2301 331 272 229 0 61 0

[startup+0.201425 s]
/proc/loadavg: 0.90 0.97 0.98 2/59 4974
/proc/meminfo: memFree=332852/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=0.06
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 739 3619 0 0 0 1 3 2 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917655360 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300322 s]
/proc/loadavg: 0.90 0.97 0.98 2/59 4974
/proc/meminfo: memFree=332852/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=0.06
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 739 3619 0 0 0 1 3 2 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917655360 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.400335 s]
/proc/loadavg: 0.90 0.97 0.98 2/59 4974
/proc/meminfo: memFree=332852/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=0.06
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 739 3619 0 0 0 1 3 2 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917655360 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700177 s]
/proc/loadavg: 0.90 0.97 0.98 2/59 4974
/proc/meminfo: memFree=332852/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=0.06
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 739 3619 0 0 0 1 3 2 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917655360 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 0.90 0.97 0.98 2/61 4990
/proc/meminfo: memFree=296744/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=0.06
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 739 3619 0 0 0 1 3 2 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917655360 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
[pid=4990] ppid=4974 vsize=53772 CPUtime=1.38
/proc/4990/stat : 4990 (cudf2lp) R 4974 4974 1733 0 -1 4202496 12752 0 0 0 131 7 0 0 20 0 1 0 120419431 55062528 11018 18446744073709551615 4194304 5690517 140735558040624 140735558036776 4297304 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/4990/statm: 13443 11018 160 366 0 13074 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 62984

[startup+3.10031 s]
/proc/loadavg: 0.90 0.97 0.98 2/61 4990
/proc/meminfo: memFree=264380/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=0.06
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 739 3619 0 0 0 1 3 2 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917655360 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
[pid=4990] ppid=4974 vsize=93028 CPUtime=2.96
/proc/4990/stat : 4990 (cudf2lp) R 4974 4974 1733 0 -1 4202496 26598 0 0 0 284 12 0 0 20 0 1 0 120419431 95260672 19870 18446744073709551615 4194304 5690517 140735558040624 140735558038280 4348974 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/4990/statm: 23257 19870 160 366 0 22888 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 102240

[startup+6.30031 s]
/proc/loadavg: 0.91 0.97 0.98 2/61 4991
/proc/meminfo: memFree=268100/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=4.79
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 764 42942 0 0 0 1 454 24 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917655360 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
[pid=4991] ppid=4974 vsize=43128 CPUtime=1.39
/proc/4991/stat : 4991 (gringo) R 4974 4974 1733 0 -1 4202496 12065 0 0 0 131 8 0 0 20 0 1 0 120419915 44163072 8931 18446744073709551615 4194304 6531320 140735251750224 140735251746040 5180567 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/4991/statm: 10782 8931 259 571 0 10203 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 52340

[startup+12.7003 s]
/proc/loadavg: 0.92 0.97 0.98 2/61 4991
/proc/meminfo: memFree=9804/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=12.31
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 801 153393 0 0 0 1 1145 85 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917654768 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 12.31
Current children cumulated vsize (KiB) 9212

[startup+25.5089 s]
/proc/loadavg: 0.93 0.97 0.98 2/62 4993
/proc/meminfo: memFree=270876/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=12.31
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 801 153393 0 0 0 1 1145 85 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917654768 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
[pid=4992] ppid=4974 vsize=142544 CPUtime=12.65
/proc/4992/stat : 4992 (clasp) R 4974 4974 1733 0 -1 4202496 41323 0 2 0 1250 15 0 0 20 0 1 0 120420692 145965056 35153 18446744073709551615 4194304 6238623 140734342731712 140734342728736 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 4 0 0
/proc/4992/statm: 35636 35153 264 500 0 35133 0
[pid=4993] ppid=4974 vsize=22040 CPUtime=0.02
/proc/4993/stat : 4993 (parse.py) S 4974 4974 1733 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 120420692 22568960 1128 18446744073709551615 4194304 6642060 140737177318912 140737177317272 139684473550624 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/4993/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 24.98
Current children cumulated vsize (KiB) 173796

[startup+51.1003 s]
/proc/loadavg: 0.95 0.97 0.98 2/62 4993
/proc/meminfo: memFree=270504/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=12.31
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 801 153393 0 0 0 1 1145 85 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917654768 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
[pid=4992] ppid=4974 vsize=142544 CPUtime=38.02
/proc/4992/stat : 4992 (clasp) R 4974 4974 1733 0 -1 4202496 41421 0 2 0 3787 15 0 0 20 0 1 0 120420692 145965056 35251 18446744073709551615 4194304 6238623 140734342731712 140734342728736 4353269 0 0 16781316 18946 0 0 0 17 0 0 0 4 0 0
/proc/4992/statm: 35636 35251 264 500 0 35133 0
[pid=4993] ppid=4974 vsize=22040 CPUtime=0.02
/proc/4993/stat : 4993 (parse.py) S 4974 4974 1733 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 120420692 22568960 1128 18446744073709551615 4194304 6642060 140737177318912 140737177317272 139684473550624 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/4993/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.35
Current children cumulated vsize (KiB) 173796

[startup+102.3 s]
/proc/loadavg: 0.98 0.97 0.98 2/62 4993
/proc/meminfo: memFree=270380/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=12.31
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 801 153393 0 0 0 1 1145 85 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917654768 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
[pid=4992] ppid=4974 vsize=142544 CPUtime=88.85
/proc/4992/stat : 4992 (clasp) R 4974 4974 1733 0 -1 4202496 41421 0 2 0 8869 16 0 0 20 0 1 0 120420692 145965056 35251 18446744073709551615 4194304 6238623 140734342731712 140734342728736 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 4 0 0
/proc/4992/statm: 35636 35251 264 500 0 35133 0
[pid=4993] ppid=4974 vsize=22040 CPUtime=0.02
/proc/4993/stat : 4993 (parse.py) S 4974 4974 1733 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 120420692 22568960 1128 18446744073709551615 4194304 6642060 140737177318912 140737177317272 139684473550624 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/4993/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.18
Current children cumulated vsize (KiB) 173796

[startup+162.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 4993
/proc/meminfo: memFree=270380/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=12.31
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 801 153393 0 0 0 1 1145 85 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917654768 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
[pid=4992] ppid=4974 vsize=142544 CPUtime=148.41
/proc/4992/stat : 4992 (clasp) R 4974 4974 1733 0 -1 4202496 41421 0 2 0 14824 17 0 0 20 0 1 0 120420692 145965056 35251 18446744073709551615 4194304 6238623 140734342731712 140734342728736 4356260 0 0 16781316 18946 0 0 0 17 0 0 0 4 0 0
/proc/4992/statm: 35636 35251 264 500 0 35133 0
[pid=4993] ppid=4974 vsize=22040 CPUtime=0.02
/proc/4993/stat : 4993 (parse.py) S 4974 4974 1733 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 120420692 22568960 1128 18446744073709551615 4194304 6642060 140737177318912 140737177317272 139684473550624 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/4993/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.74
Current children cumulated vsize (KiB) 173796

[startup+222.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 4993
/proc/meminfo: memFree=270008/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=12.31
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 801 153393 0 0 0 1 1145 85 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917654768 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
[pid=4992] ppid=4974 vsize=142544 CPUtime=207.97
/proc/4992/stat : 4992 (clasp) R 4974 4974 1733 0 -1 4202496 41500 0 2 0 20779 18 0 0 20 0 1 0 120420692 145965056 35330 18446744073709551615 4194304 6238623 140734342731712 140734342728736 4586419 0 0 16781316 18946 0 0 0 17 0 0 0 4 0 0
/proc/4992/statm: 35636 35330 264 500 0 35133 0
[pid=4993] ppid=4974 vsize=22040 CPUtime=0.02
/proc/4993/stat : 4993 (parse.py) S 4974 4974 1733 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 120420692 22568960 1128 18446744073709551615 4194304 6642060 140737177318912 140737177317272 139684473550624 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/4993/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.3
Current children cumulated vsize (KiB) 173796

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 4993
/proc/meminfo: memFree=270008/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=12.31
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 801 153393 0 0 0 1 1145 85 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917654768 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
[pid=4992] ppid=4974 vsize=142544 CPUtime=267.54
/proc/4992/stat : 4992 (clasp) R 4974 4974 1733 0 -1 4202496 41500 0 2 0 26733 21 0 0 20 0 1 0 120420692 145965056 35330 18446744073709551615 4194304 6238623 140734342731712 140734342728736 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 4 0 0
/proc/4992/statm: 35636 35330 264 500 0 35133 0
[pid=4993] ppid=4974 vsize=22040 CPUtime=0.02
/proc/4993/stat : 4993 (parse.py) S 4974 4974 1733 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 120420692 22568960 1128 18446744073709551615 4194304 6642060 140737177318912 140737177317272 139684473550624 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/4993/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.87
Current children cumulated vsize (KiB) 173796



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.6 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 4993
/proc/meminfo: memFree=270008/1022884 swapFree=0/0
[pid=4974] ppid=4973 vsize=9212 CPUtime=12.31
/proc/4974/stat : 4974 (aspcud-full) S 4973 4974 1733 0 -1 4202496 801 153393 0 0 0 1 1145 85 20 0 1 0 120419426 9433088 364 18446744073709551615 4194304 5129932 140736917656704 140736917654768 139683979867230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4974/statm: 2303 364 303 229 0 63 0
[pid=4992] ppid=4974 vsize=142544 CPUtime=287.67
/proc/4992/stat : 4992 (clasp) R 4974 4974 1733 0 -1 4202496 41500 0 2 0 28745 22 0 0 20 0 1 0 120420692 145965056 35330 18446744073709551615 4194304 6238623 140734342731712 140734342728736 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 4 0 0
/proc/4992/statm: 35636 35330 264 500 0 35133 0
[pid=4993] ppid=4974 vsize=22040 CPUtime=0.02
/proc/4993/stat : 4993 (parse.py) S 4974 4974 1733 0 -1 4202496 1305 0 13 0 1 1 0 0 20 0 1 0 120420692 22568960 1128 18446744073709551615 4194304 6642060 140737177318912 140737177317272 139684473550624 0 0 16777220 20994 0 0 0 17 0 0 0 14 0 0
/proc/4993/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300
Current children cumulated vsize (KiB) 173796

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): 302.647
CPU time (s): 300.055
CPU user time (s): 298.923
CPU system time (s): 1.13207
CPU usage (%): 99.1433
Max. virtual memory (cumulated for all children) (KiB): 474956

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.923
system time used= 1.13207
maximum resident set size= 404668
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 197314
page faults= 16
swaps= 0
block input operations= 70072
block output operations= 51200
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 105
involuntary context switches= 34450

runsolver used 0.624039 second user time and 1.05607 second system time

The end