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/e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/real/e69a0e36-9ef1-11df-9d4a-00163e46d37a.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.95 0.95 0.97 2/64 19348
/proc/meminfo: memFree=389092/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9204 CPUtime=0
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 120116305 9424896 332 18446744073709551615 4194304 5129932 140733781326176 140733781323640 140084510267168 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2301 332 272 229 0 61 0

[startup+0.149445 s]
/proc/loadavg: 0.95 0.95 0.97 2/64 19348
/proc/meminfo: memFree=389092/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=0.05
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 740 3623 0 0 0 0 3 2 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324832 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200323 s]
/proc/loadavg: 0.95 0.95 0.97 2/64 19348
/proc/meminfo: memFree=389092/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=0.05
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 740 3623 0 0 0 0 3 2 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324832 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300328 s]
/proc/loadavg: 0.95 0.95 0.97 2/64 19348
/proc/meminfo: memFree=389092/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=0.05
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 740 3623 0 0 0 0 3 2 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324832 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/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.95 0.95 0.97 2/64 19348
/proc/meminfo: memFree=389092/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=0.05
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 740 3623 0 0 0 0 3 2 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324832 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50034 s]
/proc/loadavg: 0.95 0.95 0.97 2/66 19364
/proc/meminfo: memFree=353480/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=0.05
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 740 3623 0 0 0 0 3 2 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324832 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
[pid=19364] ppid=19348 vsize=50284 CPUtime=1.41
/proc/19364/stat : 19364 (cudf2lp) R 19348 19348 1745 0 -1 4202496 14092 0 0 0 134 7 0 0 20 0 1 0 120116308 51490816 10692 18446744073709551615 4194304 5690517 140733917888544 140733917886184 4293615 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/19364/statm: 12571 10692 160 366 0 12202 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 59496

[startup+3.10027 s]
/proc/loadavg: 0.96 0.95 0.97 2/66 19364
/proc/meminfo: memFree=303632/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=2.9
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 764 27512 0 0 0 0 274 16 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324832 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 2.9
Current children cumulated vsize (KiB) 9212

[startup+6.30033 s]
/proc/loadavg: 0.96 0.95 0.97 2/66 19365
/proc/meminfo: memFree=247328/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=2.9
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 764 27512 0 0 0 0 274 16 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324832 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
[pid=19365] ppid=19348 vsize=178828 CPUtime=3.31
/proc/19365/stat : 19365 (gringo) R 19348 19348 1745 0 -1 4202496 43889 0 0 0 314 17 0 0 20 0 1 0 120116599 183119872 35122 18446744073709551615 4194304 6531320 140736728717952 140736728714568 4331287 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/19365/statm: 44707 35122 281 571 0 44128 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 188040

[startup+12.7004 s]
/proc/loadavg: 0.96 0.95 0.97 2/67 19367
/proc/meminfo: memFree=263824/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=10.22
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 802 134443 0 0 0 0 948 74 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324240 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
[pid=19366] ppid=19348 vsize=138444 CPUtime=2.2
/proc/19366/stat : 19366 (clasp) R 19348 19348 1745 0 -1 4202496 40429 0 0 0 208 12 0 0 20 0 1 0 120117349 141766656 34022 18446744073709551615 4194304 6238623 140737426081600 140737426078624 4356128 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19366/statm: 34611 34022 263 500 0 34108 0
[pid=19367] ppid=19348 vsize=22040 CPUtime=0.02
/proc/19367/stat : 19367 (parse.py) S 19348 19348 1745 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 120117349 22568960 1128 18446744073709551615 4194304 6642060 140734971195408 140734971193768 140100737705760 0 0 16777220 20994 0 0 0 17 0 0 0 12 0 0
/proc/19367/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 169696

[startup+25.5004 s]
/proc/loadavg: 0.97 0.95 0.97 2/67 19367
/proc/meminfo: memFree=263080/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=10.22
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 802 134443 0 0 0 0 948 74 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324240 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
[pid=19366] ppid=19348 vsize=138444 CPUtime=14.86
/proc/19366/stat : 19366 (clasp) R 19348 19348 1745 0 -1 4202496 40689 0 0 0 1474 12 0 0 20 0 1 0 120117349 141766656 34282 18446744073709551615 4194304 6238623 140737426081600 140737426078624 4406990 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19366/statm: 34611 34282 263 500 0 34108 0
[pid=19367] ppid=19348 vsize=22040 CPUtime=0.02
/proc/19367/stat : 19367 (parse.py) S 19348 19348 1745 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 120117349 22568960 1128 18446744073709551615 4194304 6642060 140734971195408 140734971193768 140100737705760 0 0 16777220 20994 0 0 0 17 0 0 0 12 0 0
/proc/19367/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.1
Current children cumulated vsize (KiB) 169696

[startup+51.1004 s]
/proc/loadavg: 0.98 0.95 0.97 2/67 19367
/proc/meminfo: memFree=262956/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=10.22
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 802 134443 0 0 0 0 948 74 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324240 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
[pid=19366] ppid=19348 vsize=138444 CPUtime=40.19
/proc/19366/stat : 19366 (clasp) R 19348 19348 1745 0 -1 4202496 40689 0 0 0 4007 12 0 0 20 0 1 0 120117349 141766656 34282 18446744073709551615 4194304 6238623 140737426081600 140737426078624 4696985 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19366/statm: 34611 34282 263 500 0 34108 0
[pid=19367] ppid=19348 vsize=22040 CPUtime=0.02
/proc/19367/stat : 19367 (parse.py) S 19348 19348 1745 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 120117349 22568960 1128 18446744073709551615 4194304 6642060 140734971195408 140734971193768 140100737705760 0 0 16777220 20994 0 0 0 17 0 0 0 12 0 0
/proc/19367/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.43
Current children cumulated vsize (KiB) 169696

[startup+102.3 s]
/proc/loadavg: 0.99 0.96 0.97 2/67 19375
/proc/meminfo: memFree=251052/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=10.22
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 802 134443 0 0 0 0 948 74 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324240 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
[pid=19366] ppid=19348 vsize=149444 CPUtime=90.92
/proc/19366/stat : 19366 (clasp) R 19348 19348 1745 0 -1 4202496 43456 0 0 0 9078 14 0 0 20 0 1 0 120117349 153030656 37049 18446744073709551615 4194304 6238623 140737426081600 140737426078624 4355597 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19366/statm: 37361 37049 263 500 0 36858 0
[pid=19367] ppid=19348 vsize=22040 CPUtime=0.02
/proc/19367/stat : 19367 (parse.py) S 19348 19348 1745 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 120117349 22568960 1128 18446744073709551615 4194304 6642060 140734971195408 140734971193768 140100737705760 0 0 16777220 20994 0 0 0 17 0 0 0 12 0 0
/proc/19367/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.16
Current children cumulated vsize (KiB) 180696

[startup+162.3 s]
/proc/loadavg: 1.03 0.97 0.97 2/67 19378
/proc/meminfo: memFree=135608/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=10.22
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 802 134443 0 0 0 0 948 74 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324240 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
[pid=19366] ppid=19348 vsize=269880 CPUtime=150.45
/proc/19366/stat : 19366 (clasp) R 19348 19348 1745 0 -1 4202496 71938 0 0 0 15016 29 0 0 20 0 1 0 120117349 276357120 65531 18446744073709551615 4194304 6238623 140737426081600 140737426078152 4684850 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19366/statm: 67470 65531 263 500 0 66967 0
[pid=19367] ppid=19348 vsize=22040 CPUtime=0.02
/proc/19367/stat : 19367 (parse.py) S 19348 19348 1745 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 120117349 22568960 1128 18446744073709551615 4194304 6642060 140734971195408 140734971193768 140100737705760 0 0 16777220 20994 0 0 0 17 0 0 0 12 0 0
/proc/19367/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.69
Current children cumulated vsize (KiB) 301132

[startup+222.304 s]
/proc/loadavg: 1.17 1.02 0.99 2/67 19629
/proc/meminfo: memFree=14832/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=10.22
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 802 134443 0 0 0 0 948 74 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324240 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
[pid=19366] ppid=19348 vsize=427688 CPUtime=204.4
/proc/19366/stat : 19366 (clasp) R 19348 19348 1745 0 -1 4202496 109204 0 0 0 20396 44 0 0 20 0 1 0 120117349 437952512 102797 18446744073709551615 4194304 6238623 140737426081600 140737426078624 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19366/statm: 106922 102797 263 500 0 106419 0
[pid=19367] ppid=19348 vsize=22040 CPUtime=0.02
/proc/19367/stat : 19367 (parse.py) S 19348 19348 1745 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 120117349 22568960 1128 18446744073709551615 4194304 6642060 140734971195408 140734971193768 140100737705760 0 0 16777220 20994 0 0 0 17 0 0 0 12 0 0
/proc/19367/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 214.64
Current children cumulated vsize (KiB) 458940

[startup+282.3 s]
/proc/loadavg: 1.10 1.03 1.00 2/67 19629
/proc/meminfo: memFree=10368/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=10.22
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 802 134443 0 0 0 0 948 74 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324240 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
[pid=19366] ppid=19348 vsize=470152 CPUtime=263.91
/proc/19366/stat : 19366 (clasp) R 19348 19348 1745 0 -1 4202496 119769 0 0 0 26340 51 0 0 20 0 1 0 120117349 481435648 113362 18446744073709551615 4194304 6238623 140737426081600 140737426078624 4407305 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19366/statm: 117538 113362 263 500 0 117035 0
[pid=19367] ppid=19348 vsize=22040 CPUtime=0.02
/proc/19367/stat : 19367 (parse.py) S 19348 19348 1745 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 120117349 22568960 1128 18446744073709551615 4194304 6642060 140734971195408 140734971193768 140100737705760 0 0 16777220 20994 0 0 0 17 0 0 0 12 0 0
/proc/19367/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 274.15
Current children cumulated vsize (KiB) 501404



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+308.4 s]
/proc/loadavg: 1.06 1.03 1.00 2/67 19629
/proc/meminfo: memFree=10368/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=10.22
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 802 134443 0 0 0 0 948 74 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781324240 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
[pid=19366] ppid=19348 vsize=470152 CPUtime=289.81
/proc/19366/stat : 19366 (clasp) R 19348 19348 1745 0 -1 4202496 119769 0 0 0 28929 52 0 0 20 0 1 0 120117349 481435648 113362 18446744073709551615 4194304 6238623 140737426081600 140737426078624 4333050 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19366/statm: 117538 113362 263 500 0 117035 0
[pid=19367] ppid=19348 vsize=22040 CPUtime=0.02
/proc/19367/stat : 19367 (parse.py) S 19348 19348 1745 0 -1 4202496 1306 0 13 0 1 1 0 0 20 0 1 0 120117349 22568960 1128 18446744073709551615 4194304 6642060 140734971195408 140734971193768 140100737705760 0 0 16777220 20994 0 0 0 17 0 0 0 12 0 0
/proc/19367/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.05
Current children cumulated vsize (KiB) 501404

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+308.516 s]
/proc/loadavg: 1.06 1.03 1.00 2/67 19629
/proc/meminfo: memFree=10368/1022884 swapFree=0/0
[pid=19348] ppid=19347 vsize=9212 CPUtime=300.11
/proc/19348/stat : 19348 (aspcud-full) S 19347 19348 1745 0 -1 4202496 839 255600 0 13 0 0 29879 132 20 0 1 0 120116305 9433088 365 18446744073709551615 4194304 5129932 140733781326176 140733781323728 140084510123102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19348/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 300.11
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 308.52
CPU time (s): 300.139
CPU user time (s): 298.803
CPU system time (s): 1.33608
CPU usage (%): 97.2835
Max. virtual memory (cumulated for all children) (KiB): 501404

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.803
system time used= 1.33608
maximum resident set size= 453492
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 256671
page faults= 16
swaps= 0
block input operations= 42200
block output operations= 45576
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 111
involuntary context switches= 37251

runsolver used 0.48403 second user time and 1.41609 second system time

The end