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/rand695.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand695.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/easy/rand695.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: 1.00 1.00 1.00 2/64 20222
/proc/meminfo: memFree=284740/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=3152 CPUtime=0
/proc/20222/stat : 20222 (runsolver) R 20221 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120360785 3227648 33 18446744073709551615 134512640 134586868 4290393456 4290391504 4151985200 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 788 33 0 19 0 73 0

[startup+0.197207 s]
/proc/loadavg: 1.00 1.00 1.00 2/64 20222
/proc/meminfo: memFree=284740/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=0.06
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 735 3615 0 0 1 0 4 1 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212984016 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200329 s]
/proc/loadavg: 1.00 1.00 1.00 2/64 20222
/proc/meminfo: memFree=284740/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=0.06
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 735 3615 0 0 1 0 4 1 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212984016 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300237 s]
/proc/loadavg: 1.00 1.00 1.00 2/64 20222
/proc/meminfo: memFree=284740/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=0.06
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 735 3615 0 0 1 0 4 1 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212984016 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700211 s]
/proc/loadavg: 1.00 1.00 1.00 2/64 20222
/proc/meminfo: memFree=284740/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=0.06
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 735 3615 0 0 1 0 4 1 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212984016 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.00 1.00 1.00 2/66 20238
/proc/meminfo: memFree=250120/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=0.06
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 735 3615 0 0 1 0 4 1 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212984016 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20238] ppid=20222 vsize=48864 CPUtime=1.44
/proc/20238/stat : 20238 (cudf2lp) R 20222 20222 1745 0 -1 4202496 13724 0 0 0 136 8 0 0 20 0 1 0 120360789 50036736 10326 18446744073709551615 4194304 5690517 140736913823952 140736913821592 4438130 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/20238/statm: 12216 10326 159 366 0 11847 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 58076

[startup+3.10027 s]
/proc/loadavg: 1.00 1.00 1.00 2/66 20238
/proc/meminfo: memFree=219244/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=2.95
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 761 27438 0 0 1 0 276 18 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212984016 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 2.95
Current children cumulated vsize (KiB) 9212

[startup+6.30029 s]
/proc/loadavg: 1.00 1.00 1.00 2/66 20239
/proc/meminfo: memFree=126368/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=2.95
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 761 27438 0 0 1 0 276 18 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212984016 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20239] ppid=20222 vsize=218196 CPUtime=3.29
/proc/20239/stat : 20239 (gringo) R 20222 20222 1745 0 -1 4202496 52556 0 0 0 311 18 0 0 20 0 1 0 120361082 223432704 47920 18446744073709551615 4194304 6531320 140735225115392 140735225111736 4595693 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20239/statm: 54549 47920 283 571 0 53970 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 227408

[startup+12.7004 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20241
/proc/meminfo: memFree=179916/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=7.55
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 801 101114 0 0 1 0 699 55 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212983424 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20240] ppid=20222 vsize=88788 CPUtime=4.95
/proc/20240/stat : 20240 (clasp) R 20222 20222 1745 0 -1 4202496 25823 0 0 0 484 11 0 0 20 0 1 0 120361552 90918912 21775 18446744073709551615 4194304 6238623 140734555297760 140734555294784 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20240/statm: 22197 21775 263 500 0 21694 0
[pid=20241] ppid=20222 vsize=22040 CPUtime=0.01
/proc/20241/stat : 20241 (parse.py) S 20222 20222 1745 0 -1 4202496 1314 0 4 0 1 0 0 0 20 0 1 0 120361552 22568960 1128 18446744073709551615 4194304 6642060 140733785645792 140733785644152 139873618913056 0 0 16777220 20994 0 0 0 17 0 0 0 3 0 0
/proc/20241/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.51
Current children cumulated vsize (KiB) 120040

[startup+25.5004 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20241
/proc/meminfo: memFree=179916/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=7.55
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 801 101114 0 0 1 0 699 55 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212983424 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20240] ppid=20222 vsize=88788 CPUtime=17.63
/proc/20240/stat : 20240 (clasp) R 20222 20222 1745 0 -1 4202496 25823 0 0 0 1752 11 0 0 20 0 1 0 120361552 90918912 21775 18446744073709551615 4194304 6238623 140734555297760 140734555294784 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20240/statm: 22197 21775 263 500 0 21694 0
[pid=20241] ppid=20222 vsize=22040 CPUtime=0.01
/proc/20241/stat : 20241 (parse.py) S 20222 20222 1745 0 -1 4202496 1314 0 4 0 1 0 0 0 20 0 1 0 120361552 22568960 1128 18446744073709551615 4194304 6642060 140733785645792 140733785644152 139873618913056 0 0 16777220 20994 0 0 0 17 0 0 0 3 0 0
/proc/20241/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.19
Current children cumulated vsize (KiB) 120040

[startup+51.1004 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20241
/proc/meminfo: memFree=179916/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=7.55
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 801 101114 0 0 1 0 699 55 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212983424 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20240] ppid=20222 vsize=88788 CPUtime=42.99
/proc/20240/stat : 20240 (clasp) R 20222 20222 1745 0 -1 4202496 25823 0 0 0 4288 11 0 0 20 0 1 0 120361552 90918912 21775 18446744073709551615 4194304 6238623 140734555297760 140734555294784 4687700 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20240/statm: 22197 21775 263 500 0 21694 0
[pid=20241] ppid=20222 vsize=22040 CPUtime=0.01
/proc/20241/stat : 20241 (parse.py) S 20222 20222 1745 0 -1 4202496 1314 0 4 0 1 0 0 0 20 0 1 0 120361552 22568960 1128 18446744073709551615 4194304 6642060 140733785645792 140733785644152 139873618913056 0 0 16777220 20994 0 0 0 17 0 0 0 3 0 0
/proc/20241/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.55
Current children cumulated vsize (KiB) 120040

[startup+102.3 s]
/proc/loadavg: 1.07 1.02 1.00 2/67 20241
/proc/meminfo: memFree=141228/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=7.55
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 801 101114 0 0 1 0 699 55 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212983424 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20240] ppid=20222 vsize=126940 CPUtime=93.72
/proc/20240/stat : 20240 (clasp) R 20222 20222 1745 0 -1 4202496 35473 0 0 0 9356 16 0 0 20 0 1 0 120361552 129986560 31425 18446744073709551615 4194304 6238623 140734555297760 140734555294784 4321256 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20240/statm: 31735 31425 263 500 0 31232 0
[pid=20241] ppid=20222 vsize=22040 CPUtime=0.01
/proc/20241/stat : 20241 (parse.py) S 20222 20222 1745 0 -1 4202496 1314 0 4 0 1 0 0 0 20 0 1 0 120361552 22568960 1128 18446744073709551615 4194304 6642060 140733785645792 140733785644152 139873618913056 0 0 16777220 20994 0 0 0 17 0 0 0 3 0 0
/proc/20241/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.28
Current children cumulated vsize (KiB) 158192

[startup+162.3 s]
/proc/loadavg: 1.02 1.01 1.00 2/67 20241
/proc/meminfo: memFree=71044/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=7.55
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 801 101114 0 0 1 0 699 55 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212983424 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20240] ppid=20222 vsize=199228 CPUtime=153.16
/proc/20240/stat : 20240 (clasp) R 20222 20222 1745 0 -1 4202496 53018 0 0 0 15292 24 0 0 20 0 1 0 120361552 204009472 48970 18446744073709551615 4194304 6238623 140734555297760 140734555294784 4685700 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20240/statm: 49807 48970 263 500 0 49304 0
[pid=20241] ppid=20222 vsize=22040 CPUtime=0.01
/proc/20241/stat : 20241 (parse.py) S 20222 20222 1745 0 -1 4202496 1314 0 4 0 1 0 0 0 20 0 1 0 120361552 22568960 1128 18446744073709551615 4194304 6642060 140733785645792 140733785644152 139873618913056 0 0 16777220 20994 0 0 0 17 0 0 0 3 0 0
/proc/20241/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.72
Current children cumulated vsize (KiB) 230480

[startup+222.304 s]
/proc/loadavg: 1.01 1.00 1.00 2/67 20241
/proc/meminfo: memFree=56660/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=7.55
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 801 101114 0 0 1 0 699 55 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212983424 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20240] ppid=20222 vsize=213428 CPUtime=212.62
/proc/20240/stat : 20240 (clasp) R 20222 20222 1745 0 -1 4202496 56583 0 0 0 21234 28 0 0 20 0 1 0 120361552 218550272 52535 18446744073709551615 4194304 6238623 140734555297760 140734555294784 4406972 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20240/statm: 53357 52535 263 500 0 52854 0
[pid=20241] ppid=20222 vsize=22040 CPUtime=0.01
/proc/20241/stat : 20241 (parse.py) S 20222 20222 1745 0 -1 4202496 1314 0 4 0 1 0 0 0 20 0 1 0 120361552 22568960 1128 18446744073709551615 4194304 6642060 140733785645792 140733785644152 139873618913056 0 0 16777220 20994 0 0 0 17 0 0 0 3 0 0
/proc/20241/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.18
Current children cumulated vsize (KiB) 244680

[startup+282.3 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20241
/proc/meminfo: memFree=56660/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=7.55
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 801 101114 0 0 1 0 699 55 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212983424 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20240] ppid=20222 vsize=213428 CPUtime=272.16
/proc/20240/stat : 20240 (clasp) R 20222 20222 1745 0 -1 4202496 56584 0 0 0 27187 29 0 0 20 0 1 0 120361552 218550272 52536 18446744073709551615 4194304 6238623 140734555297760 140734555294784 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20240/statm: 53357 52536 263 500 0 52854 0
[pid=20241] ppid=20222 vsize=22040 CPUtime=0.01
/proc/20241/stat : 20241 (parse.py) S 20222 20222 1745 0 -1 4202496 1314 0 4 0 1 0 0 0 20 0 1 0 120361552 22568960 1128 18446744073709551615 4194304 6642060 140733785645792 140733785644152 139873618913056 0 0 16777220 20994 0 0 0 17 0 0 0 3 0 0
/proc/20241/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.72
Current children cumulated vsize (KiB) 244680



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.8 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20241
/proc/meminfo: memFree=56660/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=7.55
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 801 101114 0 0 1 0 699 55 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212983424 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20240] ppid=20222 vsize=213428 CPUtime=292.51
/proc/20240/stat : 20240 (clasp) R 20222 20222 1745 0 -1 4202496 56584 0 0 0 29222 29 0 0 20 0 1 0 120361552 218550272 52536 18446744073709551615 4194304 6238623 140734555297760 140734555294784 4329920 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20240/statm: 53357 52536 263 500 0 52854 0
[pid=20241] ppid=20222 vsize=22040 CPUtime=0.01
/proc/20241/stat : 20241 (parse.py) S 20222 20222 1745 0 -1 4202496 1314 0 4 0 1 0 0 0 20 0 1 0 120361552 22568960 1128 18446744073709551615 4194304 6642060 140733785645792 140733785644152 139873618913056 0 0 16777220 20994 0 0 0 17 0 0 0 3 0 0
/proc/20241/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 244680

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+302.8 s]
/proc/loadavg: 1.00 1.00 1.00 2/67 20241
/proc/meminfo: memFree=56660/1022884 swapFree=0/0
[pid=20222] ppid=20221 vsize=9212 CPUtime=7.55
/proc/20222/stat : 20222 (aspcud-full) S 20221 20222 1745 0 -1 4202496 801 101114 0 0 1 0 699 55 20 0 1 0 120360785 9433088 365 18446744073709551615 4194304 5129932 140737212985360 140737212983424 139671492469854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20222/statm: 2303 365 303 229 0 63 0
[pid=20240] ppid=20222 vsize=213428 CPUtime=292.51
/proc/20240/stat : 20240 (clasp) R 20222 20222 1745 0 -1 4202496 56584 0 0 0 29222 29 0 0 20 0 1 0 120361552 218550272 52536 18446744073709551615 4194304 6238623 140734555297760 140734555294784 4329920 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20240/statm: 53357 52536 263 500 0 52854 0
[pid=20241] ppid=20222 vsize=22040 CPUtime=0.01
/proc/20241/stat : 20241 (parse.py) S 20222 20222 1745 0 -1 4202496 1314 0 4 0 1 0 0 0 20 0 1 0 120361552 22568960 1128 18446744073709551615 4194304 6642060 140733785645792 140733785644152 139873618913056 0 0 16777220 20994 0 0 0 17 0 0 0 3 0 0
/proc/20241/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.07
Current children cumulated vsize (KiB) 244680

Child status: 0
Real time (s): 302.863
CPU time (s): 300.127
CPU user time (s): 299.251
CPU system time (s): 0.876054
CPU usage (%): 99.0965
Max. virtual memory (cumulated for all children) (KiB): 323400

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.251
system time used= 0.876054
maximum resident set size= 259756
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 160126
page faults= 5
swaps= 0
block input operations= 42752
block output operations= 31464
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 79
involuntary context switches= 34383

runsolver used 0.692043 second user time and 1.33608 second system time

The end