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/rand116.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand116.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/difficult/rand116.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.87 0.96 0.98 2/64 20648
/proc/meminfo: memFree=437748/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9204 CPUtime=0
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 431 0 0 0 0 0 0 0 20 0 1 0 120554478 9424896 332 18446744073709551615 4194304 5129932 140733761861520 140733761858984 139997088388896 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2301 332 272 229 0 61 0

[startup+0.131851 s]
/proc/loadavg: 0.87 0.96 0.98 2/64 20648
/proc/meminfo: memFree=437748/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=0.05
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 739 3614 0 6 0 0 3 2 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761860176 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200329 s]
/proc/loadavg: 0.87 0.96 0.98 2/64 20648
/proc/meminfo: memFree=437748/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=0.05
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 739 3614 0 6 0 0 3 2 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761860176 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300309 s]
/proc/loadavg: 0.87 0.96 0.98 2/64 20648
/proc/meminfo: memFree=437748/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=0.05
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 739 3614 0 6 0 0 3 2 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761860176 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700228 s]
/proc/loadavg: 0.87 0.96 0.98 2/64 20648
/proc/meminfo: memFree=437748/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=0.05
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 739 3614 0 6 0 0 3 2 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761860176 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.87 0.96 0.98 2/66 20664
/proc/meminfo: memFree=403252/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=0.05
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 739 3614 0 6 0 0 3 2 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761860176 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20664] ppid=20648 vsize=33064 CPUtime=1.39
/proc/20664/stat : 20664 (cudf2lp) R 20648 20648 1745 0 -1 4202496 9702 0 0 0 135 4 0 0 20 0 1 0 120554486 33857536 7968 18446744073709551615 4194304 5690517 140734895577440 140734895575080 4961205 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/20664/statm: 8266 7968 160 366 0 7897 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 42276

[startup+3.10033 s]
/proc/loadavg: 0.87 0.96 0.98 2/66 20664
/proc/meminfo: memFree=371384/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=0.05
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 739 3614 0 6 0 0 3 2 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761860176 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20664] ppid=20648 vsize=93028 CPUtime=2.97
/proc/20664/stat : 20664 (cudf2lp) R 20648 20648 1745 0 -1 4202496 26493 0 0 0 284 13 0 0 20 0 1 0 120554486 95260672 19765 18446744073709551615 4194304 5690517 140734895577440 140734895575080 4970665 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/20664/statm: 23257 19765 160 366 0 22888 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 102240

[startup+6.30032 s]
/proc/loadavg: 0.88 0.96 0.98 2/66 20665
/proc/meminfo: memFree=378452/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=4.91
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 763 42937 0 6 0 0 467 24 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761860176 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20665] ppid=20648 vsize=39984 CPUtime=1.27
/proc/20665/stat : 20665 (gringo) R 20648 20648 1745 0 -1 4202496 11235 0 0 0 121 6 0 0 20 0 1 0 120554980 40943616 8101 18446744073709551615 4194304 6531320 140737200675952 140737200672568 4364736 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20665/statm: 9996 8101 259 571 0 9417 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 49196

[startup+12.7003 s]
/proc/loadavg: 0.89 0.96 0.98 3/66 20665
/proc/meminfo: memFree=10132/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=4.91
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 763 42937 0 6 0 0 467 24 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761860176 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20665] ppid=20648 vsize=473992 CPUtime=7.51
/proc/20665/stat : 20665 (gringo) R 20648 20648 1745 0 -1 4202496 113152 0 0 0 704 47 0 0 20 0 1 0 120554980 485367808 103221 18446744073709551615 4194304 6531320 140737200675952 140737200673624 4344262 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20665/statm: 118498 103221 284 571 0 117919 0
Current children cumulated CPU time (s) 12.42
Current children cumulated vsize (KiB) 483204

[startup+25.5004 s]
/proc/loadavg: 0.91 0.97 0.98 2/67 20667
/proc/meminfo: memFree=279492/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=12.82
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 802 156093 0 6 0 0 1196 86 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761859584 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20666] ppid=20648 vsize=145480 CPUtime=12.25
/proc/20666/stat : 20666 (clasp) R 20648 20648 1745 0 -1 4202496 42091 0 0 0 1212 13 0 0 20 0 1 0 120555787 148971520 35877 18446744073709551615 4194304 6238623 140736964159520 140736964156544 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20666/statm: 36370 35877 263 500 0 35867 0
[pid=20667] ppid=20648 vsize=22040 CPUtime=0.01
/proc/20667/stat : 20667 (parse.py) S 20648 20648 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120555787 22568960 1127 18446744073709551615 4194304 6642060 140734822712720 140734822711080 140624694343456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20667/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.08
Current children cumulated vsize (KiB) 176732

[startup+51.1004 s]
/proc/loadavg: 0.94 0.97 0.98 2/67 20667
/proc/meminfo: memFree=279492/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=12.82
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 802 156093 0 6 0 0 1196 86 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761859584 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20666] ppid=20648 vsize=145480 CPUtime=37.6
/proc/20666/stat : 20666 (clasp) R 20648 20648 1745 0 -1 4202496 42091 0 0 0 3747 13 0 0 20 0 1 0 120555787 148971520 35877 18446744073709551615 4194304 6238623 140736964159520 140736964156544 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20666/statm: 36370 35877 263 500 0 35867 0
[pid=20667] ppid=20648 vsize=22040 CPUtime=0.01
/proc/20667/stat : 20667 (parse.py) S 20648 20648 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120555787 22568960 1127 18446744073709551615 4194304 6642060 140734822712720 140734822711080 140624694343456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20667/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.43
Current children cumulated vsize (KiB) 176732

[startup+102.3 s]
/proc/loadavg: 1.04 0.99 0.99 2/67 20667
/proc/meminfo: memFree=279368/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=12.82
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 802 156093 0 6 0 0 1196 86 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761859584 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20666] ppid=20648 vsize=145480 CPUtime=88.29
/proc/20666/stat : 20666 (clasp) R 20648 20648 1745 0 -1 4202496 42091 0 0 0 8815 14 0 0 20 0 1 0 120555787 148971520 35877 18446744073709551615 4194304 6238623 140736964159520 140736964156544 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20666/statm: 36370 35877 263 500 0 35867 0
[pid=20667] ppid=20648 vsize=22040 CPUtime=0.01
/proc/20667/stat : 20667 (parse.py) S 20648 20648 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120555787 22568960 1127 18446744073709551615 4194304 6642060 140734822712720 140734822711080 140624694343456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20667/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.12
Current children cumulated vsize (KiB) 176732

[startup+162.3 s]
/proc/loadavg: 1.16 1.02 1.00 2/67 20667
/proc/meminfo: memFree=262132/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=12.82
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 802 156093 0 6 0 0 1196 86 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761859584 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20666] ppid=20648 vsize=162180 CPUtime=147.7
/proc/20666/stat : 20666 (clasp) R 20648 20648 1745 0 -1 4202496 46393 0 0 0 14754 16 0 0 20 0 1 0 120555787 166072320 40179 18446744073709551615 4194304 6238623 140736964159520 140736964156544 4676729 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20666/statm: 40545 40179 263 500 0 40042 0
[pid=20667] ppid=20648 vsize=22040 CPUtime=0.01
/proc/20667/stat : 20667 (parse.py) S 20648 20648 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120555787 22568960 1127 18446744073709551615 4194304 6642060 140734822712720 140734822711080 140624694343456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20667/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.53
Current children cumulated vsize (KiB) 193432

[startup+222.305 s]
/proc/loadavg: 1.06 1.01 1.00 2/67 20667
/proc/meminfo: memFree=242912/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=12.82
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 802 156093 0 6 0 0 1196 86 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761859584 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20666] ppid=20648 vsize=182156 CPUtime=207.14
/proc/20666/stat : 20666 (clasp) R 20648 20648 1745 0 -1 4202496 51234 0 0 0 20696 18 0 0 20 0 1 0 120555787 186527744 45020 18446744073709551615 4194304 6238623 140736964159520 140736964156544 4677123 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20666/statm: 45539 45020 263 500 0 45036 0
[pid=20667] ppid=20648 vsize=22040 CPUtime=0.01
/proc/20667/stat : 20667 (parse.py) S 20648 20648 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120555787 22568960 1127 18446744073709551615 4194304 6642060 140734822712720 140734822711080 140624694343456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20667/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 219.97
Current children cumulated vsize (KiB) 213408

[startup+282.3 s]
/proc/loadavg: 1.08 1.02 1.00 2/67 20667
/proc/meminfo: memFree=220716/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=12.82
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 802 156093 0 6 0 0 1196 86 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761859584 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20666] ppid=20648 vsize=204248 CPUtime=266.56
/proc/20666/stat : 20666 (clasp) R 20648 20648 1745 0 -1 4202496 56796 0 0 0 26632 24 0 0 20 0 1 0 120555787 209149952 50582 18446744073709551615 4194304 6238623 140736964159520 140736964156544 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20666/statm: 51062 50582 263 500 0 50559 0
[pid=20667] ppid=20648 vsize=22040 CPUtime=0.01
/proc/20667/stat : 20667 (parse.py) S 20648 20648 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120555787 22568960 1127 18446744073709551615 4194304 6642060 140734822712720 140734822711080 140624694343456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20667/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 279.39
Current children cumulated vsize (KiB) 235500



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+303.1 s]
/proc/loadavg: 1.05 1.02 1.00 2/67 20667
/proc/meminfo: memFree=220592/1022884 swapFree=0/0
[pid=20648] ppid=20647 vsize=9212 CPUtime=12.82
/proc/20648/stat : 20648 (aspcud-full) S 20647 20648 1745 0 -1 4202496 802 156093 0 6 0 0 1196 86 20 0 1 0 120554478 9433088 365 18446744073709551615 4194304 5129932 140733761861520 140733761859584 139997088244830 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20648/statm: 2303 365 303 229 0 63 0
[pid=20666] ppid=20648 vsize=204248 CPUtime=287.19
/proc/20666/stat : 20666 (clasp) R 20648 20648 1745 0 -1 4202496 56796 0 0 0 28695 24 0 0 20 0 1 0 120555787 209149952 50582 18446744073709551615 4194304 6238623 140736964159520 140736964156544 4669522 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20666/statm: 51062 50582 263 500 0 50559 0
[pid=20667] ppid=20648 vsize=22040 CPUtime=0.01
/proc/20667/stat : 20667 (parse.py) S 20648 20648 1745 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 120555787 22568960 1127 18446744073709551615 4194304 6642060 140734822712720 140734822711080 140624694343456 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20667/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.02
Current children cumulated vsize (KiB) 235500

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): 303.158
CPU time (s): 300.111
CPU user time (s): 298.947
CPU system time (s): 1.16407
CPU usage (%): 98.9948
Max. virtual memory (cumulated for all children) (KiB): 487304

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.947
system time used= 1.16407
maximum resident set size= 415488
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 215325
page faults= 6
swaps= 0
block input operations= 68640
block output operations= 52096
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 84
involuntary context switches= 34252

runsolver used 0.748046 second user time and 1.43609 second system time

The end