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/4a69cf16-c731-11df-9182-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/4a69cf16-c731-11df-9182-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/real/4a69cf16-c731-11df-9182-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: 1.00 1.00 0.99 2/64 26051
/proc/meminfo: memFree=307280/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=3152 CPUtime=0
/proc/26051/stat : 26051 (runsolver) R 26050 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 41981533 3227648 32 18446744073709551615 134512640 134586868 4293664400 4293662448 4151551024 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.197953 s]
/proc/loadavg: 1.00 1.00 0.99 2/64 26051
/proc/meminfo: memFree=307280/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=0.03
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 732 3625 0 0 0 0 3 0 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267786528 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200272 s]
/proc/loadavg: 1.00 1.00 0.99 2/64 26051
/proc/meminfo: memFree=307280/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=0.03
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 732 3625 0 0 0 0 3 0 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267786528 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300243 s]
/proc/loadavg: 1.00 1.00 0.99 2/64 26051
/proc/meminfo: memFree=307280/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=0.03
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 732 3625 0 0 0 0 3 0 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267786528 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700199 s]
/proc/loadavg: 1.00 1.00 0.99 2/64 26051
/proc/meminfo: memFree=307280/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=0.03
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 732 3625 0 0 0 0 3 0 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267786528 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50027 s]
/proc/loadavg: 1.00 1.00 0.99 2/66 26067
/proc/meminfo: memFree=247324/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=0.03
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 732 3625 0 0 0 0 3 0 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267786528 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26067] ppid=26051 vsize=56724 CPUtime=1.44
/proc/26067/stat : 26067 (cudf2lp) R 26051 26051 32685 0 -1 4202496 16766 0 0 0 139 5 0 0 20 0 1 0 41981536 58085376 13367 18446744073709551615 4194304 5690517 140734305545808 140734305543160 4326870 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/26067/statm: 14181 13367 165 366 0 13812 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 65936

[startup+3.10027 s]
/proc/loadavg: 1.00 1.00 0.99 2/66 26068
/proc/meminfo: memFree=269356/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=2.03
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 756 29068 0 0 0 0 193 10 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267786528 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26068] ppid=26051 vsize=60964 CPUtime=1.02
/proc/26068/stat : 26068 (gringo) R 26051 26051 32685 0 -1 4202496 15958 0 0 0 94 8 0 0 20 0 1 0 41981739 62427136 13338 18446744073709551615 4194304 6531320 140733621231616 140733621228232 4360993 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/26068/statm: 15241 13338 278 571 0 14662 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 70176

[startup+6.30026 s]
/proc/loadavg: 1.08 1.02 1.00 2/66 26068
/proc/meminfo: memFree=10012/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=2.03
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 756 29068 0 0 0 0 193 10 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267786528 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26068] ppid=26051 vsize=426380 CPUtime=4.1
/proc/26068/stat : 26068 (gringo) R 26051 26051 32685 0 -1 4202496 99732 0 0 0 379 31 0 0 20 0 1 0 41981739 436613120 90966 18446744073709551615 4194304 6531320 140733621231616 140733621228520 4361008 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/26068/statm: 106595 90966 283 571 0 106016 0
Current children cumulated CPU time (s) 6.13
Current children cumulated vsize (KiB) 435592

[startup+12.7003 s]
/proc/loadavg: 1.07 1.02 1.00 2/67 26070
/proc/meminfo: memFree=267596/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=6.86
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 793 138011 0 0 0 0 632 54 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267785936 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26069] ppid=26051 vsize=141536 CPUtime=5.6
/proc/26069/stat : 26069 (clasp) R 26051 26051 32685 0 -1 4202496 41493 0 0 0 548 12 0 0 20 0 1 0 41982237 144932864 35035 18446744073709551615 4194304 6238623 140734669599904 140734669596928 4331870 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26069/statm: 35384 35035 263 500 0 34881 0
[pid=26070] ppid=26051 vsize=22040 CPUtime=0.01
/proc/26070/stat : 26070 (parse.py) S 26051 26051 32685 0 -1 4202496 1308 0 10 0 0 1 0 0 20 0 1 0 41982237 22568960 1128 18446744073709551615 4194304 6642060 140735351953360 140735351951720 139997293356832 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/26070/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 172788

[startup+25.5004 s]
/proc/loadavg: 1.06 1.02 1.00 2/67 26070
/proc/meminfo: memFree=248872/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=6.86
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 793 138011 0 0 0 0 632 54 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267785936 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26069] ppid=26051 vsize=160032 CPUtime=18.32
/proc/26069/stat : 26069 (clasp) R 26051 26051 32685 0 -1 4202496 46149 0 0 0 1820 12 0 0 20 0 1 0 41982237 163872768 39691 18446744073709551615 4194304 6238623 140734669599904 140734669596456 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26069/statm: 40008 39691 263 500 0 39505 0
[pid=26070] ppid=26051 vsize=22040 CPUtime=0.01
/proc/26070/stat : 26070 (parse.py) S 26051 26051 32685 0 -1 4202496 1308 0 10 0 0 1 0 0 20 0 1 0 41982237 22568960 1128 18446744073709551615 4194304 6642060 140735351953360 140735351951720 139997293356832 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/26070/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.19
Current children cumulated vsize (KiB) 191284

[startup+51.1003 s]
/proc/loadavg: 1.04 1.01 1.00 2/67 26070
/proc/meminfo: memFree=145580/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=6.86
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 793 138011 0 0 0 0 632 54 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267785936 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26069] ppid=26051 vsize=277288 CPUtime=43.78
/proc/26069/stat : 26069 (clasp) R 26051 26051 32685 0 -1 4202496 74010 0 0 0 4355 23 0 0 20 0 1 0 41982237 283942912 67552 18446744073709551615 4194304 6238623 140734669599904 140734669596456 4684893 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26069/statm: 69322 67552 263 500 0 68819 0
[pid=26070] ppid=26051 vsize=22040 CPUtime=0.01
/proc/26070/stat : 26070 (parse.py) S 26051 26051 32685 0 -1 4202496 1308 0 10 0 0 1 0 0 20 0 1 0 41982237 22568960 1128 18446744073709551615 4194304 6642060 140735351953360 140735351951720 139997293356832 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/26070/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.65
Current children cumulated vsize (KiB) 308540

[startup+102.3 s]
/proc/loadavg: 1.01 1.01 1.00 2/67 26070
/proc/meminfo: memFree=17116/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=6.86
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 793 138011 0 0 0 0 632 54 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267785936 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26069] ppid=26051 vsize=397104 CPUtime=94.69
/proc/26069/stat : 26069 (clasp) R 26051 26051 32685 0 -1 4202496 103967 0 0 0 9432 37 0 0 20 0 1 0 41982237 406634496 97509 18446744073709551615 4194304 6238623 140734669599904 140734669596456 4687690 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26069/statm: 99276 97509 263 500 0 98773 0
[pid=26070] ppid=26051 vsize=22040 CPUtime=0.01
/proc/26070/stat : 26070 (parse.py) S 26051 26051 32685 0 -1 4202496 1308 0 10 0 0 1 0 0 20 0 1 0 41982237 22568960 1128 18446744073709551615 4194304 6642060 140735351953360 140735351951720 139997293356832 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/26070/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.56
Current children cumulated vsize (KiB) 428356

[startup+162.3 s]
/proc/loadavg: 1.09 1.03 1.01 2/63 26182
/proc/meminfo: memFree=12412/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=6.86
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 793 138011 0 0 0 0 632 54 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267785936 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26069] ppid=26051 vsize=532464 CPUtime=151.43
/proc/26069/stat : 26069 (clasp) R 26051 26051 32685 0 -1 4202496 135521 0 0 0 15092 51 0 0 20 0 1 0 41982237 545243136 129063 18446744073709551615 4194304 6238623 140734669599904 140734669596456 4697083 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26069/statm: 133116 129063 263 500 0 132613 0
[pid=26070] ppid=26051 vsize=22040 CPUtime=0.01
/proc/26070/stat : 26070 (parse.py) S 26051 26051 32685 0 -1 4202496 1308 0 10 0 0 1 0 0 20 0 1 0 41982237 22568960 1128 18446744073709551615 4194304 6642060 140735351953360 140735351951720 139997293356832 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/26070/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 158.3
Current children cumulated vsize (KiB) 563716

[startup+222.303 s]
/proc/loadavg: 1.03 1.02 1.00 2/63 26182
/proc/meminfo: memFree=11172/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=6.86
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 793 138011 0 0 0 0 632 54 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267785936 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26069] ppid=26051 vsize=533672 CPUtime=211.1
/proc/26069/stat : 26069 (clasp) R 26051 26051 32685 0 -1 4202496 135847 0 0 0 21058 52 0 0 20 0 1 0 41982237 546480128 129389 18446744073709551615 4194304 6238623 140734669599904 140734669596928 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26069/statm: 133418 129389 263 500 0 132915 0
[pid=26070] ppid=26051 vsize=22040 CPUtime=0.01
/proc/26070/stat : 26070 (parse.py) S 26051 26051 32685 0 -1 4202496 1308 0 10 0 0 1 0 0 20 0 1 0 41982237 22568960 1128 18446744073709551615 4194304 6642060 140735351953360 140735351951720 139997293356832 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/26070/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 217.97
Current children cumulated vsize (KiB) 564924

[startup+282.3 s]
/proc/loadavg: 1.01 1.02 1.00 2/63 26182
/proc/meminfo: memFree=9312/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=6.86
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 793 138011 0 0 0 0 632 54 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267785936 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26069] ppid=26051 vsize=538340 CPUtime=270.77
/proc/26069/stat : 26069 (clasp) R 26051 26051 32685 0 -1 4202496 137648 0 0 0 27025 52 0 0 20 0 1 0 41982237 551260160 131190 18446744073709551615 4194304 6238623 140734669599904 140734669596928 4687697 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26069/statm: 134585 131190 263 500 0 134082 0
[pid=26070] ppid=26051 vsize=22040 CPUtime=0.01
/proc/26070/stat : 26070 (parse.py) S 26051 26051 32685 0 -1 4202496 1308 0 10 0 0 1 0 0 20 0 1 0 41982237 22568960 1128 18446744073709551615 4194304 6642060 140735351953360 140735351951720 139997293356832 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/26070/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 277.64
Current children cumulated vsize (KiB) 569592



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+304.803 s]
/proc/loadavg: 1.01 1.02 1.00 2/63 26182
/proc/meminfo: memFree=10056/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=6.86
/proc/26051/stat : 26051 (aspcud-full) S 26050 26051 32685 0 -1 4202496 793 138011 0 0 0 0 632 54 20 0 1 0 41981533 9433088 364 18446744073709551615 4194304 5129932 140736267787872 140736267785936 140486302614622 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 364 303 229 0 63 0
[pid=26069] ppid=26051 vsize=539412 CPUtime=293.15
/proc/26069/stat : 26069 (clasp) R 26051 26051 32685 0 -1 4202496 137916 0 0 0 29262 53 0 0 20 0 1 0 41982237 552357888 131458 18446744073709551615 4194304 6238623 140734669599904 140734669596456 4635597 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/26069/statm: 134853 131458 263 500 0 134350 0
[pid=26070] ppid=26051 vsize=22040 CPUtime=0.01
/proc/26070/stat : 26070 (parse.py) S 26051 26051 32685 0 -1 4202496 1308 0 10 0 0 1 0 0 20 0 1 0 41982237 22568960 1128 18446744073709551615 4194304 6642060 140735351953360 140735351951720 139997293356832 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/26070/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.02
Current children cumulated vsize (KiB) 570664

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+304.974 s]
/proc/loadavg: 1.01 1.02 1.00 2/63 26182
/proc/meminfo: memFree=10056/1022884 swapFree=0/0
[pid=26051] ppid=26050 vsize=9212 CPUtime=300.17
/proc/26051/stat : 26051 (aspcud-full) D 26050 26051 32685 0 -1 4202496 843 277524 0 13 0 0 29902 115 20 0 1 0 41981533 9433088 365 18446744073709551615 4194304 5129932 140736267787872 140736267785016 140486307835128 0 0 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/26051/statm: 2303 365 304 229 0 63 0
Current children cumulated CPU time (s) 300.17
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 304.985
CPU time (s): 300.187
CPU user time (s): 299.027
CPU system time (s): 1.16007
CPU usage (%): 98.4266
Max. virtual memory (cumulated for all children) (KiB): 570664

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 299.027
system time used= 1.16007
maximum resident set size= 525872
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 278368
page faults= 14
swaps= 0
block input operations= 45312
block output operations= 46872
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 101
involuntary context switches= 6228

runsolver used 0.572035 second user time and 1.11607 second system time

The end