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/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/real/8b0e7c16-bab4-11e0-a883-00163e1e087d.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.88 0.95 0.98 2/59 20456
/proc/meminfo: memFree=361992/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=3152 CPUtime=0
/proc/20456/stat : 20456 (runsolver) R 20455 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 120210323 3227648 33 18446744073709551615 134512640 134586868 4292538992 4292537040 4151850032 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.122129 s]
/proc/loadavg: 0.88 0.95 0.98 2/59 20456
/proc/meminfo: memFree=361992/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=0.04
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 733 3621 0 0 0 0 3 1 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194624 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200319 s]
/proc/loadavg: 0.88 0.95 0.98 2/59 20456
/proc/meminfo: memFree=361992/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=0.04
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 733 3621 0 0 0 0 3 1 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194624 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.30031 s]
/proc/loadavg: 0.88 0.95 0.98 2/59 20456
/proc/meminfo: memFree=361992/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=0.04
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 733 3621 0 0 0 0 3 1 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194624 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700238 s]
/proc/loadavg: 0.88 0.95 0.98 2/59 20456
/proc/meminfo: memFree=361992/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=0.04
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 733 3621 0 0 0 0 3 1 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194624 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.88 0.95 0.98 2/61 20472
/proc/meminfo: memFree=325636/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=0.04
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 733 3621 0 0 0 0 3 1 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194624 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20472] ppid=20456 vsize=50452 CPUtime=1.43
/proc/20472/stat : 20472 (cudf2lp) R 20456 20456 1750 0 -1 4202496 14245 0 0 0 136 7 0 0 20 0 1 0 120210327 51662848 10846 18446744073709551615 4194304 5690517 140737112087616 140737112085256 4293666 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/20472/statm: 12613 10846 160 366 0 12244 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 59664

[startup+3.10033 s]
/proc/loadavg: 0.88 0.95 0.98 2/61 20472
/proc/meminfo: memFree=292652/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=0.04
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 733 3621 0 0 0 0 3 1 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194624 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20472] ppid=20456 vsize=84504 CPUtime=3.01
/proc/20472/stat : 20472 (cudf2lp) R 20456 20456 1750 0 -1 4202496 27255 0 0 0 286 15 0 0 20 0 1 0 120210327 86532096 20854 18446744073709551615 4194304 5690517 140737112087616 140737112084984 4956989 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/20472/statm: 21126 20854 174 366 0 20757 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 93716

[startup+6.30031 s]
/proc/loadavg: 0.89 0.96 0.98 2/61 20473
/proc/meminfo: memFree=233628/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=3.18
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 757 30878 0 0 0 0 298 20 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194624 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20473] ppid=20456 vsize=153248 CPUtime=3.06
/proc/20473/stat : 20473 (gringo) R 20456 20456 1750 0 -1 4202496 37030 0 0 0 284 22 0 0 20 0 1 0 120210645 156925952 32361 18446744073709551615 4194304 6531320 140735484186048 140735484183112 4359156 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20473/statm: 38312 32361 282 571 0 37733 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 162460

[startup+12.7004 s]
/proc/loadavg: 0.90 0.96 0.98 2/62 20475
/proc/meminfo: memFree=233452/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=9.64
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 794 126007 0 0 0 0 888 76 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194032 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20474] ppid=20456 vsize=121724 CPUtime=2.8
/proc/20474/stat : 20474 (clasp) R 20456 20456 1750 0 -1 4202496 35721 0 1 0 267 13 0 0 20 0 1 0 120211306 124645376 29808 18446744073709551615 4194304 6238623 140733308078656 140733308075680 4406990 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/20474/statm: 30431 29808 263 500 0 29928 0
[pid=20475] ppid=20456 vsize=22040 CPUtime=0.02
/proc/20475/stat : 20475 (parse.py) S 20456 20456 1750 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 120211306 22568960 1129 18446744073709551615 4194304 6642060 140733958082720 140733958081080 140115335759648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20475/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.46
Current children cumulated vsize (KiB) 152976

[startup+25.5004 s]
/proc/loadavg: 0.92 0.96 0.98 2/62 20475
/proc/meminfo: memFree=233452/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=9.64
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 794 126007 0 0 0 0 888 76 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194032 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20474] ppid=20456 vsize=121724 CPUtime=15.48
/proc/20474/stat : 20474 (clasp) R 20456 20456 1750 0 -1 4202496 35721 0 1 0 1535 13 0 0 20 0 1 0 120211306 124645376 29808 18446744073709551615 4194304 6238623 140733308078656 140733308075680 4407219 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/20474/statm: 30431 29808 263 500 0 29928 0
[pid=20475] ppid=20456 vsize=22040 CPUtime=0.02
/proc/20475/stat : 20475 (parse.py) S 20456 20456 1750 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 120211306 22568960 1129 18446744073709551615 4194304 6642060 140733958082720 140733958081080 140115335759648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20475/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 152976

[startup+51.1004 s]
/proc/loadavg: 0.95 0.96 0.98 2/62 20475
/proc/meminfo: memFree=233328/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=9.64
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 794 126007 0 0 0 0 888 76 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194032 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20474] ppid=20456 vsize=121724 CPUtime=40.84
/proc/20474/stat : 20474 (clasp) R 20456 20456 1750 0 -1 4202496 35721 0 1 0 4070 14 0 0 20 0 1 0 120211306 124645376 29808 18446744073709551615 4194304 6238623 140733308078656 140733308075680 4406960 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/20474/statm: 30431 29808 263 500 0 29928 0
[pid=20475] ppid=20456 vsize=22040 CPUtime=0.02
/proc/20475/stat : 20475 (parse.py) S 20456 20456 1750 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 120211306 22568960 1129 18446744073709551615 4194304 6642060 140733958082720 140733958081080 140115335759648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20475/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.5
Current children cumulated vsize (KiB) 152976

[startup+102.3 s]
/proc/loadavg: 0.97 0.96 0.98 2/62 20475
/proc/meminfo: memFree=233328/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=9.64
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 794 126007 0 0 0 0 888 76 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194032 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20474] ppid=20456 vsize=121724 CPUtime=91.63
/proc/20474/stat : 20474 (clasp) R 20456 20456 1750 0 -1 4202496 35721 0 1 0 9148 15 0 0 20 0 1 0 120211306 124645376 29808 18446744073709551615 4194304 6238623 140733308078656 140733308075680 4407305 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/20474/statm: 30431 29808 263 500 0 29928 0
[pid=20475] ppid=20456 vsize=22040 CPUtime=0.02
/proc/20475/stat : 20475 (parse.py) S 20456 20456 1750 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 120211306 22568960 1129 18446744073709551615 4194304 6642060 140733958082720 140733958081080 140115335759648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20475/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 101.29
Current children cumulated vsize (KiB) 152976

[startup+162.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 20475
/proc/meminfo: memFree=233328/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=9.64
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 794 126007 0 0 0 0 888 76 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194032 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20474] ppid=20456 vsize=121724 CPUtime=151.17
/proc/20474/stat : 20474 (clasp) R 20456 20456 1750 0 -1 4202496 35724 0 1 0 15101 16 0 0 20 0 1 0 120211306 124645376 29811 18446744073709551615 4194304 6238623 140733308078656 140733308075680 4421741 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/20474/statm: 30431 29811 263 500 0 29928 0
[pid=20475] ppid=20456 vsize=22040 CPUtime=0.02
/proc/20475/stat : 20475 (parse.py) S 20456 20456 1750 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 120211306 22568960 1129 18446744073709551615 4194304 6642060 140733958082720 140733958081080 140115335759648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20475/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 160.83
Current children cumulated vsize (KiB) 152976

[startup+222.309 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 20475
/proc/meminfo: memFree=224152/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=9.64
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 794 126007 0 0 0 0 888 76 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194032 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20474] ppid=20456 vsize=130044 CPUtime=210.73
/proc/20474/stat : 20474 (clasp) R 20456 20456 1750 0 -1 4202496 38117 0 1 0 21054 19 0 0 20 0 1 0 120211306 133165056 32204 18446744073709551615 4194304 6238623 140733308078656 140733308075680 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/20474/statm: 32511 32204 263 500 0 32008 0
[pid=20475] ppid=20456 vsize=22040 CPUtime=0.02
/proc/20475/stat : 20475 (parse.py) S 20456 20456 1750 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 120211306 22568960 1129 18446744073709551615 4194304 6642060 140733958082720 140733958081080 140115335759648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20475/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 220.39
Current children cumulated vsize (KiB) 161296

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 20475
/proc/meminfo: memFree=169592/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=9.64
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 794 126007 0 0 0 0 888 76 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194032 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20474] ppid=20456 vsize=185248 CPUtime=270.28
/proc/20474/stat : 20474 (clasp) R 20456 20456 1750 0 -1 4202496 51895 0 1 0 27001 27 0 0 20 0 1 0 120211306 189693952 45982 18446744073709551615 4194304 6238623 140733308078656 140733308075680 4407054 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/20474/statm: 46312 45982 263 500 0 45809 0
[pid=20475] ppid=20456 vsize=22040 CPUtime=0.02
/proc/20475/stat : 20475 (parse.py) S 20456 20456 1750 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 120211306 22568960 1129 18446744073709551615 4194304 6642060 140733958082720 140733958081080 140115335759648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20475/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 279.94
Current children cumulated vsize (KiB) 216500



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.5 s]
/proc/loadavg: 0.99 0.97 0.98 3/62 20475
/proc/meminfo: memFree=153844/1022884 swapFree=0/0
[pid=20456] ppid=20455 vsize=9212 CPUtime=9.64
/proc/20456/stat : 20456 (aspcud-full) S 20455 20456 1750 0 -1 4202496 794 126007 0 0 0 0 888 76 20 0 1 0 120210323 9433088 365 18446744073709551615 4194304 5129932 140736029195968 140736029194032 140288140682334 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20456/statm: 2303 365 303 229 0 63 0
[pid=20474] ppid=20456 vsize=200204 CPUtime=290.34
/proc/20474/stat : 20474 (clasp) R 20456 20456 1750 0 -1 4202496 55650 0 1 0 29004 30 0 0 20 0 1 0 120211306 205008896 49737 18446744073709551615 4194304 6238623 140733308078656 140733308075680 4407237 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/20474/statm: 50051 49737 263 500 0 49548 0
[pid=20475] ppid=20456 vsize=22040 CPUtime=0.02
/proc/20475/stat : 20475 (parse.py) S 20456 20456 1750 0 -1 4202496 1319 0 0 0 2 0 0 0 20 0 1 0 120211306 22568960 1129 18446744073709551615 4194304 6642060 140733958082720 140733958081080 140115335759648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20475/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 300
Current children cumulated vsize (KiB) 231456

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): 302.544
CPU time (s): 300.067
CPU user time (s): 298.967
CPU system time (s): 1.10007
CPU usage (%): 99.1812
Max. virtual memory (cumulated for all children) (KiB): 422640

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.967
system time used= 1.10007
maximum resident set size= 345436
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 184123
page faults= 1
swaps= 0
block input operations= 43544
block output operations= 42736
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 87
involuntary context switches= 34528

runsolver used 0.508031 second user time and 1.24008 second system time

The end