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/rand307.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand307.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/upgrade/easy/rand307.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.86 0.97 0.98 2/60 26315
/proc/meminfo: memFree=454808/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=3152 CPUtime=0
/proc/26315/stat : 26315 (runsolver) R 26314 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 42061812 3227648 32 18446744073709551615 134512640 134586868 4291421792 4291419840 4152009776 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 788 32 0 19 0 73 0

[startup+0.12877 s]
/proc/loadavg: 0.86 0.97 0.98 2/60 26315
/proc/meminfo: memFree=454808/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=0.03
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 734 3629 0 0 0 0 3 0 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522164016 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200276 s]
/proc/loadavg: 0.86 0.97 0.98 2/60 26315
/proc/meminfo: memFree=454808/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=0.03
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 734 3629 0 0 0 0 3 0 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522164016 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300251 s]
/proc/loadavg: 0.86 0.97 0.98 2/60 26315
/proc/meminfo: memFree=454808/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=0.03
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 734 3629 0 0 0 0 3 0 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522164016 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.70019 s]
/proc/loadavg: 0.86 0.97 0.98 2/60 26315
/proc/meminfo: memFree=454808/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=0.03
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 734 3629 0 0 0 0 3 0 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522164016 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50024 s]
/proc/loadavg: 0.86 0.97 0.98 2/62 26331
/proc/meminfo: memFree=398240/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=0.03
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 734 3629 0 0 0 0 3 0 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522164016 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26331] ppid=26315 vsize=48864 CPUtime=1.38
/proc/26331/stat : 26331 (cudf2lp) R 26315 26315 32685 0 -1 4202496 14548 0 0 0 130 8 0 0 20 0 1 0 42061814 50036736 11150 18446744073709551615 4194304 5690517 140734721511792 140734721509432 4293680 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/26331/statm: 12216 11150 160 366 0 11847 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 58076

[startup+3.10026 s]
/proc/loadavg: 0.86 0.97 0.98 2/62 26332
/proc/meminfo: memFree=419196/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=1.96
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 760 27452 0 0 0 0 183 13 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522164016 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26332] ppid=26315 vsize=87020 CPUtime=1.04
/proc/26332/stat : 26332 (gringo) R 26315 26315 32685 0 -1 4202496 22265 0 0 0 97 7 0 0 20 0 1 0 42062017 89108480 17629 18446744073709551615 4194304 6531320 140735913209152 140735913205080 5554437 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/26332/statm: 21755 17629 281 571 0 21176 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 96232

[startup+6.30032 s]
/proc/loadavg: 0.87 0.97 0.98 2/63 26334
/proc/meminfo: memFree=325692/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=4.94
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 800 101033 0 0 0 0 456 38 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522163424 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26333] ppid=26315 vsize=88676 CPUtime=1.23
/proc/26333/stat : 26333 (clasp) R 26315 26315 32685 0 -1 4202496 25702 0 0 0 116 7 0 0 20 0 1 0 42062316 90804224 21656 18446744073709551615 4194304 6238623 140735637673568 140735637670592 4635196 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26333/statm: 22169 21656 264 500 0 21666 0
[pid=26334] ppid=26315 vsize=22040 CPUtime=0.01
/proc/26334/stat : 26334 (parse.py) S 26315 26315 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 42062316 22568960 1128 18446744073709551615 4194304 6642060 140733995596400 140733995594760 140230673749792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26334/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 119928

[startup+12.7004 s]
/proc/loadavg: 0.88 0.97 0.98 2/63 26334
/proc/meminfo: memFree=328420/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=4.94
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 800 101033 0 0 0 0 456 38 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522163424 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26333] ppid=26315 vsize=88676 CPUtime=7.58
/proc/26333/stat : 26333 (clasp) R 26315 26315 32685 0 -1 4202496 25793 0 0 0 751 7 0 0 20 0 1 0 42062316 90804224 21747 18446744073709551615 4194304 6238623 140735637673568 140735637670592 4356222 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26333/statm: 22169 21747 264 500 0 21666 0
[pid=26334] ppid=26315 vsize=22040 CPUtime=0.01
/proc/26334/stat : 26334 (parse.py) S 26315 26315 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 42062316 22568960 1128 18446744073709551615 4194304 6642060 140733995596400 140733995594760 140230673749792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26334/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.53
Current children cumulated vsize (KiB) 119928

[startup+25.5004 s]
/proc/loadavg: 0.91 0.97 0.98 2/63 26334
/proc/meminfo: memFree=328296/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=4.94
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 800 101033 0 0 0 0 456 38 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522163424 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26333] ppid=26315 vsize=88676 CPUtime=20.28
/proc/26333/stat : 26333 (clasp) R 26315 26315 32685 0 -1 4202496 25793 0 0 0 2020 8 0 0 20 0 1 0 42062316 90804224 21747 18446744073709551615 4194304 6238623 140735637673568 140735637670592 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26333/statm: 22169 21747 264 500 0 21666 0
[pid=26334] ppid=26315 vsize=22040 CPUtime=0.01
/proc/26334/stat : 26334 (parse.py) S 26315 26315 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 42062316 22568960 1128 18446744073709551615 4194304 6642060 140733995596400 140733995594760 140230673749792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26334/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 119928

[startup+51.1004 s]
/proc/loadavg: 0.94 0.97 0.98 2/63 26342
/proc/meminfo: memFree=327924/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=4.94
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 800 101033 0 0 0 0 456 38 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522163424 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26333] ppid=26315 vsize=88676 CPUtime=45.65
/proc/26333/stat : 26333 (clasp) R 26315 26315 32685 0 -1 4202496 25793 0 0 0 4557 8 0 0 20 0 1 0 42062316 90804224 21747 18446744073709551615 4194304 6238623 140735637673568 140735637670592 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26333/statm: 22169 21747 264 500 0 21666 0
[pid=26334] ppid=26315 vsize=22040 CPUtime=0.01
/proc/26334/stat : 26334 (parse.py) S 26315 26315 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 42062316 22568960 1128 18446744073709551615 4194304 6642060 140733995596400 140733995594760 140230673749792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26334/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.6
Current children cumulated vsize (KiB) 119928

[startup+102.3 s]
/proc/loadavg: 0.97 0.97 0.98 2/63 26342
/proc/meminfo: memFree=327924/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=4.94
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 800 101033 0 0 0 0 456 38 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522163424 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26333] ppid=26315 vsize=88676 CPUtime=96.47
/proc/26333/stat : 26333 (clasp) R 26315 26315 32685 0 -1 4202496 25793 0 0 0 9638 9 0 0 20 0 1 0 42062316 90804224 21747 18446744073709551615 4194304 6238623 140735637673568 140735637670592 4406990 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26333/statm: 22169 21747 264 500 0 21666 0
[pid=26334] ppid=26315 vsize=22040 CPUtime=0.01
/proc/26334/stat : 26334 (parse.py) S 26315 26315 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 42062316 22568960 1128 18446744073709551615 4194304 6642060 140733995596400 140733995594760 140230673749792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26334/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.42
Current children cumulated vsize (KiB) 119928

[startup+162.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/63 26342
/proc/meminfo: memFree=327924/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=4.94
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 800 101033 0 0 0 0 456 38 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522163424 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26333] ppid=26315 vsize=88676 CPUtime=156.02
/proc/26333/stat : 26333 (clasp) R 26315 26315 32685 0 -1 4202496 25793 0 0 0 15592 10 0 0 20 0 1 0 42062316 90804224 21747 18446744073709551615 4194304 6238623 140735637673568 140735637670592 4407247 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26333/statm: 22169 21747 264 500 0 21666 0
[pid=26334] ppid=26315 vsize=22040 CPUtime=0.01
/proc/26334/stat : 26334 (parse.py) S 26315 26315 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 42062316 22568960 1128 18446744073709551615 4194304 6642060 140733995596400 140733995594760 140230673749792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26334/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.97
Current children cumulated vsize (KiB) 119928

[startup+222.307 s]
/proc/loadavg: 0.99 0.97 0.98 2/63 26342
/proc/meminfo: memFree=327924/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=4.94
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 800 101033 0 0 0 0 456 38 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522163424 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26333] ppid=26315 vsize=88676 CPUtime=215.61
/proc/26333/stat : 26333 (clasp) R 26315 26315 32685 0 -1 4202496 25793 0 0 0 21549 12 0 0 20 0 1 0 42062316 90804224 21747 18446744073709551615 4194304 6238623 140735637673568 140735637670592 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26333/statm: 22169 21747 264 500 0 21666 0
[pid=26334] ppid=26315 vsize=22040 CPUtime=0.01
/proc/26334/stat : 26334 (parse.py) S 26315 26315 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 42062316 22568960 1128 18446744073709551615 4194304 6642060 140733995596400 140733995594760 140230673749792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26334/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.56
Current children cumulated vsize (KiB) 119928

[startup+282.3 s]
/proc/loadavg: 1.04 0.99 0.99 2/59 26454
/proc/meminfo: memFree=328584/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=4.94
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 800 101033 0 0 0 0 456 38 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522163424 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26333] ppid=26315 vsize=88676 CPUtime=272.58
/proc/26333/stat : 26333 (clasp) R 26315 26315 32685 0 -1 4202496 25793 0 0 0 27239 19 0 0 20 0 1 0 42062316 90804224 21747 18446744073709551615 4194304 6238623 140735637673568 140735637670592 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26333/statm: 22169 21747 264 500 0 21666 0
[pid=26334] ppid=26315 vsize=22040 CPUtime=0.01
/proc/26334/stat : 26334 (parse.py) S 26315 26315 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 42062316 22568960 1128 18446744073709551615 4194304 6642060 140733995596400 140733995594760 140230673749792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26334/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 277.53
Current children cumulated vsize (KiB) 119928



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+304.9 s]
/proc/loadavg: 1.03 0.99 0.99 2/59 26454
/proc/meminfo: memFree=328708/1022884 swapFree=0/0
[pid=26315] ppid=26314 vsize=9212 CPUtime=4.94
/proc/26315/stat : 26315 (aspcud-full) S 26314 26315 32685 0 -1 4202496 800 101033 0 0 0 0 456 38 20 0 1 0 42061812 9433088 364 18446744073709551615 4194304 5129932 140736522165360 140736522163424 139766682547294 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26315/statm: 2303 364 303 229 0 63 0
[pid=26333] ppid=26315 vsize=88676 CPUtime=295.06
/proc/26333/stat : 26333 (clasp) R 26315 26315 32685 0 -1 4202496 25793 0 0 0 29485 21 0 0 20 0 1 0 42062316 90804224 21747 18446744073709551615 4194304 6238623 140735637673568 140735637670592 4407017 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26333/statm: 22169 21747 264 500 0 21666 0
[pid=26334] ppid=26315 vsize=22040 CPUtime=0.01
/proc/26334/stat : 26334 (parse.py) S 26315 26315 32685 0 -1 4202496 1318 0 0 0 1 0 0 0 20 0 1 0 42062316 22568960 1128 18446744073709551615 4194304 6642060 140733995596400 140733995594760 140230673749792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/26334/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.01
Current children cumulated vsize (KiB) 119928

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): 304.926
CPU time (s): 300.059
CPU user time (s): 299.451
CPU system time (s): 0.608038
CPU usage (%): 98.4037
Max. virtual memory (cumulated for all children) (KiB): 323176

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.451
system time used= 0.608038
maximum resident set size= 259376
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 129259
page faults= 0
swaps= 0
block input operations= 42376
block output operations= 31416
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 76
involuntary context switches= 5516

runsolver used 0.768048 second user time and 1.27208 second system time

The end