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/easy/rand736.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand736.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/easy/rand736.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

[startup+0 s]
/proc/loadavg: 0.92 0.98 0.99 2/59 4611
/proc/meminfo: memFree=298916/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=3152 CPUtime=0
/proc/4611/stat : 4611 (runsolver) R 4610 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120291010 3227648 32 18446744073709551615 134512640 134586868 4286946416 4286944464 4152149040 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.205624 s]
/proc/loadavg: 0.92 0.98 0.99 2/59 4611
/proc/meminfo: memFree=298916/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=0.05
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 741 3616 0 0 0 1 2 2 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199741168 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300294 s]
/proc/loadavg: 0.92 0.98 0.99 2/59 4611
/proc/meminfo: memFree=298916/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=0.05
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 741 3616 0 0 0 1 2 2 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199741168 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.40029 s]
/proc/loadavg: 0.92 0.98 0.99 2/59 4611
/proc/meminfo: memFree=298916/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=0.05
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 741 3616 0 0 0 1 2 2 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199741168 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700217 s]
/proc/loadavg: 0.92 0.98 0.99 2/59 4611
/proc/meminfo: memFree=298916/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=0.05
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 741 3616 0 0 0 1 2 2 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199741168 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 0.92 0.98 0.99 2/61 4627
/proc/meminfo: memFree=262684/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=0.05
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 741 3616 0 0 0 1 2 2 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199741168 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
[pid=4627] ppid=4611 vsize=48864 CPUtime=1.42
/proc/4627/stat : 4627 (cudf2lp) R 4611 4611 1733 0 -1 4202496 13700 0 0 0 134 8 0 0 20 0 1 0 120291014 50036736 10302 18446744073709551615 4194304 5690517 140736966243440 140736966241080 4360947 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/4627/statm: 12216 10302 159 366 0 11847 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 58076

[startup+3.10023 s]
/proc/loadavg: 0.93 0.98 0.99 2/61 4627
/proc/meminfo: memFree=222012/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=2.96
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 768 27440 0 0 0 1 278 17 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199741168 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 9212

[startup+6.30028 s]
/proc/loadavg: 0.93 0.98 0.99 2/61 4628
/proc/meminfo: memFree=138188/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=2.96
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 768 27440 0 0 0 1 278 17 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199741168 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
[pid=4628] ppid=4611 vsize=216412 CPUtime=3.26
/proc/4628/stat : 4628 (gringo) R 4611 4611 1733 0 -1 4202496 51491 0 0 0 302 24 0 0 20 0 1 0 120291310 221605888 46855 18446744073709551615 4194304 6531320 140735164105296 140735164101912 5632288 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/4628/statm: 54103 46855 283 571 0 53524 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 225624

[startup+12.7004 s]
/proc/loadavg: 0.94 0.98 0.99 2/62 4630
/proc/meminfo: memFree=179844/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=7.65
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 808 101571 0 0 0 1 703 61 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199740576 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
[pid=4629] ppid=4611 vsize=89996 CPUtime=4.87
/proc/4629/stat : 4629 (clasp) R 4611 4611 1733 0 -1 4202496 26167 0 0 0 478 9 0 0 20 0 1 0 120291785 92155904 22085 18446744073709551615 4194304 6238623 140736766941856 140736766938880 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4629/statm: 22499 22085 263 500 0 21996 0
[pid=4630] ppid=4611 vsize=22040 CPUtime=0.02
/proc/4630/stat : 4630 (parse.py) S 4611 4611 1733 0 -1 4202496 1310 0 7 0 1 1 0 0 20 0 1 0 120291785 22568960 1127 18446744073709551615 4194304 6642060 140737482708928 140737482707288 140068575225632 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/4630/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 121248

[startup+25.5042 s]
/proc/loadavg: 0.95 0.98 0.99 2/62 4630
/proc/meminfo: memFree=179720/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=7.65
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 808 101571 0 0 0 1 703 61 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199740576 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
[pid=4629] ppid=4611 vsize=89996 CPUtime=17.55
/proc/4629/stat : 4629 (clasp) R 4611 4611 1733 0 -1 4202496 26167 0 0 0 1746 9 0 0 20 0 1 0 120291785 92155904 22085 18446744073709551615 4194304 6238623 140736766941856 140736766938880 4332520 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4629/statm: 22499 22085 263 500 0 21996 0
[pid=4630] ppid=4611 vsize=22040 CPUtime=0.02
/proc/4630/stat : 4630 (parse.py) S 4611 4611 1733 0 -1 4202496 1310 0 7 0 1 1 0 0 20 0 1 0 120291785 22568960 1127 18446744073709551615 4194304 6642060 140737482708928 140737482707288 140068575225632 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/4630/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.22
Current children cumulated vsize (KiB) 121248

[startup+51.1004 s]
/proc/loadavg: 0.96 0.98 0.99 2/62 4630
/proc/meminfo: memFree=179596/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=7.65
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 808 101571 0 0 0 1 703 61 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199740576 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
[pid=4629] ppid=4611 vsize=89996 CPUtime=42.91
/proc/4629/stat : 4629 (clasp) R 4611 4611 1733 0 -1 4202496 26167 0 0 0 4282 9 0 0 20 0 1 0 120291785 92155904 22085 18446744073709551615 4194304 6238623 140736766941856 140736766938880 4305088 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4629/statm: 22499 22085 263 500 0 21996 0
[pid=4630] ppid=4611 vsize=22040 CPUtime=0.02
/proc/4630/stat : 4630 (parse.py) S 4611 4611 1733 0 -1 4202496 1310 0 7 0 1 1 0 0 20 0 1 0 120291785 22568960 1127 18446744073709551615 4194304 6642060 140737482708928 140737482707288 140068575225632 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/4630/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.58
Current children cumulated vsize (KiB) 121248

[startup+102.3 s]
/proc/loadavg: 0.98 0.98 0.99 2/62 4630
/proc/meminfo: memFree=179472/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=7.65
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 808 101571 0 0 0 1 703 61 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199740576 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
[pid=4629] ppid=4611 vsize=89996 CPUtime=93.64
/proc/4629/stat : 4629 (clasp) R 4611 4611 1733 0 -1 4202496 26167 0 0 0 9355 9 0 0 20 0 1 0 120291785 92155904 22085 18446744073709551615 4194304 6238623 140736766941856 140736766938880 4687700 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4629/statm: 22499 22085 263 500 0 21996 0
[pid=4630] ppid=4611 vsize=22040 CPUtime=0.02
/proc/4630/stat : 4630 (parse.py) S 4611 4611 1733 0 -1 4202496 1310 0 7 0 1 1 0 0 20 0 1 0 120291785 22568960 1127 18446744073709551615 4194304 6642060 140737482708928 140737482707288 140068575225632 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/4630/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.31
Current children cumulated vsize (KiB) 121248

[startup+162.3 s]
/proc/loadavg: 0.99 0.98 0.99 2/62 4630
/proc/meminfo: memFree=175132/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=7.65
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 808 101571 0 0 0 1 703 61 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199740576 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
[pid=4629] ppid=4611 vsize=93960 CPUtime=153.12
/proc/4629/stat : 4629 (clasp) R 4611 4611 1733 0 -1 4202496 27252 0 0 0 15302 10 0 0 20 0 1 0 120291785 96215040 23170 18446744073709551615 4194304 6238623 140736766941856 140736766938880 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4629/statm: 23490 23170 263 500 0 22987 0
[pid=4630] ppid=4611 vsize=22040 CPUtime=0.02
/proc/4630/stat : 4630 (parse.py) S 4611 4611 1733 0 -1 4202496 1310 0 7 0 1 1 0 0 20 0 1 0 120291785 22568960 1127 18446744073709551615 4194304 6642060 140737482708928 140737482707288 140068575225632 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/4630/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.79
Current children cumulated vsize (KiB) 125212

[startup+222.3 s]
/proc/loadavg: 0.99 0.98 0.99 2/62 4630
/proc/meminfo: memFree=139048/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=7.65
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 808 101571 0 0 0 1 703 61 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199740576 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
[pid=4629] ppid=4611 vsize=130340 CPUtime=212.68
/proc/4629/stat : 4629 (clasp) R 4611 4611 1733 0 -1 4202496 36284 0 0 0 21252 16 0 0 20 0 1 0 120291785 133468160 32202 18446744073709551615 4194304 6238623 140736766941856 140736766938880 4406998 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4629/statm: 32585 32202 263 500 0 32082 0
[pid=4630] ppid=4611 vsize=22040 CPUtime=0.02
/proc/4630/stat : 4630 (parse.py) S 4611 4611 1733 0 -1 4202496 1310 0 7 0 1 1 0 0 20 0 1 0 120291785 22568960 1127 18446744073709551615 4194304 6642060 140737482708928 140737482707288 140068575225632 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/4630/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 220.35
Current children cumulated vsize (KiB) 161592

[startup+282.3 s]
/proc/loadavg: 0.99 0.98 0.99 2/62 4630
/proc/meminfo: memFree=83000/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=7.65
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 808 101571 0 0 0 1 703 61 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199740576 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
[pid=4629] ppid=4611 vsize=186448 CPUtime=272.26
/proc/4629/stat : 4629 (clasp) R 4611 4611 1733 0 -1 4202496 50318 0 0 0 27200 26 0 0 20 0 1 0 120291785 190922752 46236 18446744073709551615 4194304 6238623 140736766941856 140736766938880 4687659 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4629/statm: 46612 46236 263 500 0 46109 0
[pid=4630] ppid=4611 vsize=22040 CPUtime=0.02
/proc/4630/stat : 4630 (parse.py) S 4611 4611 1733 0 -1 4202496 1310 0 7 0 1 1 0 0 20 0 1 0 120291785 22568960 1127 18446744073709551615 4194304 6642060 140737482708928 140737482707288 140068575225632 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/4630/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 279.93
Current children cumulated vsize (KiB) 217700



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.6 s]
/proc/loadavg: 0.99 0.98 0.99 2/62 4630
/proc/meminfo: memFree=82876/1022884 swapFree=0/0
[pid=4611] ppid=4610 vsize=9212 CPUtime=7.65
/proc/4611/stat : 4611 (aspcud-full) S 4610 4611 1733 0 -1 4202496 808 101571 0 0 0 1 703 61 20 0 1 0 120291010 9433088 364 18446744073709551615 4194304 5129932 140736199742512 140736199740576 140607627670622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/4611/statm: 2303 364 303 229 0 63 0
[pid=4629] ppid=4611 vsize=186448 CPUtime=292.42
/proc/4629/stat : 4629 (clasp) R 4611 4611 1733 0 -1 4202496 50331 0 0 0 29216 26 0 0 20 0 1 0 120291785 190922752 46249 18446744073709551615 4194304 6238623 140736766941856 140736766938880 4687700 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/4629/statm: 46612 46249 263 500 0 46109 0
[pid=4630] ppid=4611 vsize=22040 CPUtime=0.02
/proc/4630/stat : 4630 (parse.py) S 4611 4611 1733 0 -1 4202496 1310 0 7 0 1 1 0 0 20 0 1 0 120291785 22568960 1127 18446744073709551615 4194304 6642060 140737482708928 140737482707288 140068575225632 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/4630/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.09
Current children cumulated vsize (KiB) 217700

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.655
CPU time (s): 300.135
CPU user time (s): 299.215
CPU system time (s): 0.920057
CPU usage (%): 99.1674
Max. virtual memory (cumulated for all children) (KiB): 328284

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.215
system time used= 0.920057
maximum resident set size= 261576
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 154332
page faults= 8
swaps= 0
block input operations= 43216
block output operations= 31664
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 86
involuntary context switches= 34298

runsolver used 0.524032 second user time and 1.29608 second system time

The end