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/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.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.99 0.97 1.00 2/59 20078
/proc/meminfo: memFree=368196/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=3152 CPUtime=0
/proc/20078/stat : 20078 (runsolver) R 20077 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120143582 3227648 32 18446744073709551615 134512640 134586868 4288195152 4288193200 4151583792 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.175486 s]
/proc/loadavg: 0.99 0.97 1.00 2/59 20078
/proc/meminfo: memFree=368196/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=0.05
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010592 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200332 s]
/proc/loadavg: 0.99 0.97 1.00 2/59 20078
/proc/meminfo: memFree=368196/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=0.05
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010592 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.30031 s]
/proc/loadavg: 0.99 0.97 1.00 2/59 20078
/proc/meminfo: memFree=368196/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=0.05
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010592 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.70023 s]
/proc/loadavg: 0.99 0.97 1.00 2/59 20078
/proc/meminfo: memFree=368196/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=0.05
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010592 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/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.99 0.97 1.00 2/61 20094
/proc/meminfo: memFree=333452/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=0.05
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010592 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
[pid=20094] ppid=20078 vsize=57900 CPUtime=1.38
/proc/20094/stat : 20094 (cudf2lp) R 20078 20078 1750 0 -1 4202496 14289 0 0 0 132 6 0 0 20 0 1 0 120143586 59289600 12555 18446744073709551615 4194304 5690517 140733521815248 140733521811416 4956080 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/20094/statm: 14475 12555 160 366 0 14106 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 67112

[startup+3.10092 s]
/proc/loadavg: 0.99 0.97 1.00 2/61 20094
/proc/meminfo: memFree=300592/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=3.02
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 757 28570 0 0 0 0 286 16 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010592 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 9212

[startup+6.30037 s]
/proc/loadavg: 0.99 0.97 1.00 2/61 20095
/proc/meminfo: memFree=229540/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=3.02
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 757 28570 0 0 0 0 286 16 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010592 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
[pid=20095] ppid=20078 vsize=163276 CPUtime=3.16
/proc/20095/stat : 20095 (gringo) R 20078 20078 1750 0 -1 4202496 40119 0 0 0 295 21 0 0 20 0 1 0 120143892 167194624 35450 18446744073709551615 4194304 6531320 140733237793024 140733237788952 4595894 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20095/statm: 40819 35450 283 571 0 40240 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 172488

[startup+12.7004 s]
/proc/loadavg: 0.99 0.97 1.00 2/62 20097
/proc/meminfo: memFree=215880/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=8.89
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 794 116817 0 0 0 0 822 67 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010000 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
[pid=20096] ppid=20078 vsize=111448 CPUtime=3.6
/proc/20096/stat : 20096 (clasp) R 20078 20078 1750 0 -1 4202496 32948 0 0 0 347 13 0 0 20 0 1 0 120144485 114122752 27200 18446744073709551615 4194304 6238623 140734152810640 140734152807664 4356183 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20096/statm: 27862 27200 263 500 0 27359 0
[pid=20097] ppid=20078 vsize=22040 CPUtime=0.01
/proc/20097/stat : 20097 (parse.py) S 20078 20078 1750 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 120144485 22568960 1127 18446744073709551615 4194304 6642060 140736517138192 140736517136552 140229136672544 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20097/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.5
Current children cumulated vsize (KiB) 142700

[startup+25.5003 s]
/proc/loadavg: 0.99 0.97 1.00 2/62 20097
/proc/meminfo: memFree=215880/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=8.89
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 794 116817 0 0 0 0 822 67 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010000 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
[pid=20096] ppid=20078 vsize=111448 CPUtime=16.29
/proc/20096/stat : 20096 (clasp) R 20078 20078 1750 0 -1 4202496 32948 0 0 0 1616 13 0 0 20 0 1 0 120144485 114122752 27200 18446744073709551615 4194304 6238623 140734152810640 140734152807664 4407044 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20096/statm: 27862 27200 263 500 0 27359 0
[pid=20097] ppid=20078 vsize=22040 CPUtime=0.01
/proc/20097/stat : 20097 (parse.py) S 20078 20078 1750 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 120144485 22568960 1127 18446744073709551615 4194304 6642060 140736517138192 140736517136552 140229136672544 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20097/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.19
Current children cumulated vsize (KiB) 142700

[startup+51.1003 s]
/proc/loadavg: 0.99 0.97 1.00 2/62 20097
/proc/meminfo: memFree=215756/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=8.89
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 794 116817 0 0 0 0 822 67 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010000 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
[pid=20096] ppid=20078 vsize=111448 CPUtime=41.67
/proc/20096/stat : 20096 (clasp) R 20078 20078 1750 0 -1 4202496 32948 0 0 0 4153 14 0 0 20 0 1 0 120144485 114122752 27200 18446744073709551615 4194304 6238623 140734152810640 140734152807664 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20096/statm: 27862 27200 263 500 0 27359 0
[pid=20097] ppid=20078 vsize=22040 CPUtime=0.01
/proc/20097/stat : 20097 (parse.py) S 20078 20078 1750 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 120144485 22568960 1127 18446744073709551615 4194304 6642060 140736517138192 140736517136552 140229136672544 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20097/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.57
Current children cumulated vsize (KiB) 142700

[startup+102.3 s]
/proc/loadavg: 0.99 0.97 1.00 2/62 20097
/proc/meminfo: memFree=215756/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=8.89
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 794 116817 0 0 0 0 822 67 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010000 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
[pid=20096] ppid=20078 vsize=111448 CPUtime=92.39
/proc/20096/stat : 20096 (clasp) R 20078 20078 1750 0 -1 4202496 32971 0 0 0 9224 15 0 0 20 0 1 0 120144485 114122752 27223 18446744073709551615 4194304 6238623 140734152810640 140734152807664 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20096/statm: 27862 27223 263 500 0 27359 0
[pid=20097] ppid=20078 vsize=22040 CPUtime=0.01
/proc/20097/stat : 20097 (parse.py) S 20078 20078 1750 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 120144485 22568960 1127 18446744073709551615 4194304 6642060 140736517138192 140736517136552 140229136672544 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20097/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.29
Current children cumulated vsize (KiB) 142700

[startup+162.3 s]
/proc/loadavg: 0.99 0.97 1.00 2/62 20097
/proc/meminfo: memFree=214640/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=8.89
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 794 116817 0 0 0 0 822 67 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010000 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
[pid=20096] ppid=20078 vsize=111448 CPUtime=151.85
/proc/20096/stat : 20096 (clasp) R 20078 20078 1750 0 -1 4202496 33275 0 0 0 15169 16 0 0 20 0 1 0 120144485 114122752 27527 18446744073709551615 4194304 6238623 140734152810640 140734152807664 4663111 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20096/statm: 27862 27527 263 500 0 27359 0
[pid=20097] ppid=20078 vsize=22040 CPUtime=0.01
/proc/20097/stat : 20097 (parse.py) S 20078 20078 1750 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 120144485 22568960 1127 18446744073709551615 4194304 6642060 140736517138192 140736517136552 140229136672544 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20097/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.75
Current children cumulated vsize (KiB) 142700

[startup+222.303 s]
/proc/loadavg: 1.11 1.00 1.01 2/62 20348
/proc/meminfo: memFree=68800/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=8.89
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 794 116817 0 0 0 0 822 67 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010000 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
[pid=20096] ppid=20078 vsize=111448 CPUtime=206
/proc/20096/stat : 20096 (clasp) R 20078 20078 1750 0 -1 4202496 33275 0 0 0 20580 20 0 0 20 0 1 0 120144485 114122752 27527 18446744073709551615 4194304 6238623 140734152810640 140734152807664 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20096/statm: 27862 27527 263 500 0 27359 0
[pid=20097] ppid=20078 vsize=22040 CPUtime=0.01
/proc/20097/stat : 20097 (parse.py) S 20078 20078 1750 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 120144485 22568960 1127 18446744073709551615 4194304 6642060 140736517138192 140736517136552 140229136672544 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20097/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 214.9
Current children cumulated vsize (KiB) 142700

[startup+282.3 s]
/proc/loadavg: 1.04 1.00 1.00 2/62 20348
/proc/meminfo: memFree=68800/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=8.89
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 794 116817 0 0 0 0 822 67 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010000 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
[pid=20096] ppid=20078 vsize=111448 CPUtime=265.55
/proc/20096/stat : 20096 (clasp) R 20078 20078 1750 0 -1 4202496 33275 0 0 0 26533 22 0 0 20 0 1 0 120144485 114122752 27527 18446744073709551615 4194304 6238623 140734152810640 140734152807664 4407011 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20096/statm: 27862 27527 263 500 0 27359 0
[pid=20097] ppid=20078 vsize=22040 CPUtime=0.01
/proc/20097/stat : 20097 (parse.py) S 20078 20078 1750 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 120144485 22568960 1127 18446744073709551615 4194304 6642060 140736517138192 140736517136552 140229136672544 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20097/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 274.45
Current children cumulated vsize (KiB) 142700



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+308.103 s]
/proc/loadavg: 1.03 1.00 1.00 2/62 20348
/proc/meminfo: memFree=69048/1022884 swapFree=0/0
[pid=20078] ppid=20077 vsize=9212 CPUtime=8.89
/proc/20078/stat : 20078 (aspcud-full) S 20077 20078 1750 0 -1 4202496 794 116817 0 0 0 0 822 67 20 0 1 0 120143582 9433088 365 18446744073709551615 4194304 5129932 140734749011936 140734749010000 140438941357150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20078/statm: 2303 365 303 229 0 63 0
[pid=20096] ppid=20078 vsize=111448 CPUtime=291.16
/proc/20096/stat : 20096 (clasp) R 20078 20078 1750 0 -1 4202496 33275 0 0 0 29094 22 0 0 20 0 1 0 120144485 114122752 27527 18446744073709551615 4194304 6238623 140734152810640 140734152807664 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/20096/statm: 27862 27527 263 500 0 27359 0
[pid=20097] ppid=20078 vsize=22040 CPUtime=0.01
/proc/20097/stat : 20097 (parse.py) S 20078 20078 1750 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 120144485 22568960 1127 18446744073709551615 4194304 6642060 140736517138192 140736517136552 140229136672544 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20097/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300.06
Current children cumulated vsize (KiB) 142700

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): 308.135
CPU time (s): 300.135
CPU user time (s): 299.207
CPU system time (s): 0.928058
CPU usage (%): 97.4037
Max. virtual memory (cumulated for all children) (KiB): 381900

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.207
system time used= 0.928058
maximum resident set size= 317908
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 152555
page faults= 0
swaps= 0
block input operations= 43032
block output operations= 39080
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 86
involuntary context switches= 36742

runsolver used 0.576036 second user time and 1.30008 second system time

The end