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/rand874.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand874.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/difficult/rand874.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.86 1.00 0.99 2/64 20614
/proc/meminfo: memFree=320808/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=3152 CPUtime=0
/proc/20614/stat : 20614 (runsolver) R 20613 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120522165 3227648 33 18446744073709551615 134512640 134586868 4292428832 4292426880 4151522352 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.156162 s]
/proc/loadavg: 0.86 1.00 0.99 2/64 20614
/proc/meminfo: memFree=320808/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=0.03
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 734 3622 0 0 0 0 3 0 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270314080 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200261 s]
/proc/loadavg: 0.86 1.00 0.99 2/64 20614
/proc/meminfo: memFree=320808/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=0.03
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 734 3622 0 0 0 0 3 0 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270314080 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300252 s]
/proc/loadavg: 0.86 1.00 0.99 2/64 20614
/proc/meminfo: memFree=320808/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=0.03
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 734 3622 0 0 0 0 3 0 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270314080 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700207 s]
/proc/loadavg: 0.86 1.00 0.99 2/64 20614
/proc/meminfo: memFree=320808/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=0.03
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 734 3622 0 0 0 0 3 0 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270314080 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 0.86 1.00 0.99 2/66 20630
/proc/meminfo: memFree=263124/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=0.03
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 734 3622 0 0 0 0 3 0 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270314080 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20630] ppid=20614 vsize=50676 CPUtime=1.44
/proc/20630/stat : 20630 (cudf2lp) R 20614 20614 1745 0 -1 4202496 15048 0 0 0 136 8 0 0 20 0 1 0 120522168 51892224 11650 18446744073709551615 4194304 5690517 140733919407856 140733919405496 4680353 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/20630/statm: 12669 11650 160 366 0 12300 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 59888

[startup+3.10029 s]
/proc/loadavg: 0.87 1.00 0.99 2/66 20630
/proc/meminfo: memFree=210796/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=0.03
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 734 3622 0 0 0 0 3 0 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270314080 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20630] ppid=20614 vsize=114764 CPUtime=3.02
/proc/20630/stat : 20630 (cudf2lp) R 20614 20614 1745 0 -1 4202496 39321 0 0 0 282 20 0 0 20 0 1 0 120522168 117518336 28365 18446744073709551615 4194304 5690517 140733919407856 140733919405048 4641930 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/20630/statm: 28691 28365 174 366 0 28322 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 123976

[startup+6.30025 s]
/proc/loadavg: 0.87 1.00 0.99 2/66 20631
/proc/meminfo: memFree=132428/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=3.33
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 758 42945 0 0 0 0 310 23 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270314080 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20631] ppid=20614 vsize=254312 CPUtime=2.9
/proc/20631/stat : 20631 (gringo) R 20614 20614 1745 0 -1 4202496 62504 0 0 0 269 21 0 0 20 0 1 0 120522503 260415488 53225 18446744073709551615 4194304 6531320 140736987804224 140736987800664 5808234 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20631/statm: 63578 53225 283 571 0 62999 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 263524

[startup+12.7003 s]
/proc/loadavg: 0.89 1.00 0.99 2/67 20633
/proc/meminfo: memFree=270260/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=8.55
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 795 153352 0 0 0 0 786 69 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270313488 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20632] ppid=20614 vsize=142520 CPUtime=3.89
/proc/20632/stat : 20632 (clasp) R 20614 20614 1745 0 -1 4202496 41367 0 0 0 377 12 0 0 20 0 1 0 120523041 145940480 35195 18446744073709551615 4194304 6238623 140734419010112 140734419007136 4355597 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20632/statm: 35630 35195 263 500 0 35127 0
[pid=20633] ppid=20614 vsize=22040 CPUtime=0.01
/proc/20633/stat : 20633 (parse.py) S 20614 20614 1745 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120523041 22568960 1127 18446744073709551615 4194304 6642060 140736680252912 140736680251272 140645293274912 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/20633/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 173772

[startup+25.5004 s]
/proc/loadavg: 0.91 1.00 0.99 2/67 20633
/proc/meminfo: memFree=269640/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=8.55
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 795 153352 0 0 0 0 786 69 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270313488 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20632] ppid=20614 vsize=142520 CPUtime=16.58
/proc/20632/stat : 20632 (clasp) R 20614 20614 1745 0 -1 4202496 41495 0 0 0 1646 12 0 0 20 0 1 0 120523041 145940480 35323 18446744073709551615 4194304 6238623 140734419010112 140734419007136 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20632/statm: 35630 35323 263 500 0 35127 0
[pid=20633] ppid=20614 vsize=22040 CPUtime=0.01
/proc/20633/stat : 20633 (parse.py) S 20614 20614 1745 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120523041 22568960 1127 18446744073709551615 4194304 6642060 140736680252912 140736680251272 140645293274912 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/20633/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 173772

[startup+51.1004 s]
/proc/loadavg: 0.94 1.00 0.99 2/67 20633
/proc/meminfo: memFree=269516/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=8.55
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 795 153352 0 0 0 0 786 69 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270313488 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20632] ppid=20614 vsize=142520 CPUtime=41.97
/proc/20632/stat : 20632 (clasp) R 20614 20614 1745 0 -1 4202496 41495 0 0 0 4185 12 0 0 20 0 1 0 120523041 145940480 35323 18446744073709551615 4194304 6238623 140734419010112 140734419007136 4332570 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20632/statm: 35630 35323 263 500 0 35127 0
[pid=20633] ppid=20614 vsize=22040 CPUtime=0.01
/proc/20633/stat : 20633 (parse.py) S 20614 20614 1745 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120523041 22568960 1127 18446744073709551615 4194304 6642060 140736680252912 140736680251272 140645293274912 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/20633/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.53
Current children cumulated vsize (KiB) 173772

[startup+102.3 s]
/proc/loadavg: 0.97 1.00 0.99 2/67 20633
/proc/meminfo: memFree=269516/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=8.55
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 795 153352 0 0 0 0 786 69 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270313488 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20632] ppid=20614 vsize=142520 CPUtime=92.78
/proc/20632/stat : 20632 (clasp) R 20614 20614 1745 0 -1 4202496 41495 0 0 0 9266 12 0 0 20 0 1 0 120523041 145940480 35323 18446744073709551615 4194304 6238623 140734419010112 140734419007136 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20632/statm: 35630 35323 263 500 0 35127 0
[pid=20633] ppid=20614 vsize=22040 CPUtime=0.01
/proc/20633/stat : 20633 (parse.py) S 20614 20614 1745 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120523041 22568960 1127 18446744073709551615 4194304 6642060 140736680252912 140736680251272 140645293274912 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/20633/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.34
Current children cumulated vsize (KiB) 173772

[startup+162.3 s]
/proc/loadavg: 0.99 1.00 0.99 2/67 20641
/proc/meminfo: memFree=204788/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=8.55
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 795 153352 0 0 0 0 786 69 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270313488 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20632] ppid=20614 vsize=206808 CPUtime=152.28
/proc/20632/stat : 20632 (clasp) R 20614 20614 1745 0 -1 4202496 57562 0 0 0 15207 21 0 0 20 0 1 0 120523041 211771392 51390 18446744073709551615 4194304 6238623 140734419010112 140734419006664 4333424 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20632/statm: 51702 51390 263 500 0 51199 0
[pid=20633] ppid=20614 vsize=22040 CPUtime=0.01
/proc/20633/stat : 20633 (parse.py) S 20614 20614 1745 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120523041 22568960 1127 18446744073709551615 4194304 6642060 140736680252912 140736680251272 140645293274912 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/20633/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.84
Current children cumulated vsize (KiB) 238060

[startup+222.304 s]
/proc/loadavg: 0.99 1.00 0.99 2/67 20641
/proc/meminfo: memFree=109556/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=8.55
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 795 153352 0 0 0 0 786 69 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270313488 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20632] ppid=20614 vsize=303108 CPUtime=211.83
/proc/20632/stat : 20632 (clasp) R 20614 20614 1745 0 -1 4202496 81374 0 0 0 21150 33 0 0 20 0 1 0 120523041 310382592 75202 18446744073709551615 4194304 6238623 140734419010112 140734419006664 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20632/statm: 75777 75202 263 500 0 75274 0
[pid=20633] ppid=20614 vsize=22040 CPUtime=0.01
/proc/20633/stat : 20633 (parse.py) S 20614 20614 1745 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120523041 22568960 1127 18446744073709551615 4194304 6642060 140736680252912 140736680251272 140645293274912 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/20633/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 220.39
Current children cumulated vsize (KiB) 334360

[startup+282.3 s]
/proc/loadavg: 0.99 1.00 0.99 2/67 20641
/proc/meminfo: memFree=109556/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=8.55
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 795 153352 0 0 0 0 786 69 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270313488 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20632] ppid=20614 vsize=303108 CPUtime=271.27
/proc/20632/stat : 20632 (clasp) R 20614 20614 1745 0 -1 4202496 81390 0 0 0 27094 33 0 0 20 0 1 0 120523041 310382592 75218 18446744073709551615 4194304 6238623 140734419010112 140734419006664 4306755 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20632/statm: 75777 75218 263 500 0 75274 0
[pid=20633] ppid=20614 vsize=22040 CPUtime=0.01
/proc/20633/stat : 20633 (parse.py) S 20614 20614 1745 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120523041 22568960 1127 18446744073709551615 4194304 6642060 140736680252912 140736680251272 140645293274912 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/20633/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 279.83
Current children cumulated vsize (KiB) 334360



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.7 s]
/proc/loadavg: 0.99 1.00 0.99 2/67 20641
/proc/meminfo: memFree=109432/1022884 swapFree=0/0
[pid=20614] ppid=20613 vsize=9212 CPUtime=8.55
/proc/20614/stat : 20614 (aspcud-full) S 20613 20614 1745 0 -1 4202496 795 153352 0 0 0 0 786 69 20 0 1 0 120522165 9433088 365 18446744073709551615 4194304 5129932 140733270315424 140733270313488 139656162796638 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20614/statm: 2303 365 303 229 0 63 0
[pid=20632] ppid=20614 vsize=303108 CPUtime=291.49
/proc/20632/stat : 20632 (clasp) R 20614 20614 1745 0 -1 4202496 81390 0 0 0 29116 33 0 0 20 0 1 0 120523041 310382592 75218 18446744073709551615 4194304 6238623 140734419010112 140734419006664 4747984 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20632/statm: 75777 75218 263 500 0 75274 0
[pid=20633] ppid=20614 vsize=22040 CPUtime=0.01
/proc/20633/stat : 20633 (parse.py) S 20614 20614 1745 0 -1 4202496 1304 0 13 0 1 0 0 0 20 0 1 0 120523041 22568960 1127 18446744073709551615 4194304 6642060 140736680252912 140736680251272 140645293274912 0 0 16777220 20994 0 0 0 17 0 0 0 13 0 0
/proc/20633/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.05
Current children cumulated vsize (KiB) 334360

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.753
CPU time (s): 300.119
CPU user time (s): 299.051
CPU system time (s): 1.06807
CPU usage (%): 99.1298
Max. virtual memory (cumulated for all children) (KiB): 474616

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.051
system time used= 1.06807
maximum resident set size= 404496
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 237154
page faults= 13
swaps= 0
block input operations= 69824
block output operations= 51192
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 93
involuntary context switches= 34432

runsolver used 0.560035 second user time and 1.25608 second system time

The end