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/5698a62c-c731-11df-9bb9-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/5698a62c-c731-11df-9bb9-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/real/5698a62c-c731-11df-9bb9-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.90 0.95 0.97 2/60 25575
/proc/meminfo: memFree=377632/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=3152 CPUtime=0
/proc/25575/stat : 25575 (runsolver) R 25574 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 41901007 3227648 32 18446744073709551615 134512640 134586868 4293991328 4293989376 4151358512 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.135605 s]
/proc/loadavg: 0.90 0.95 0.97 2/60 25575
/proc/meminfo: memFree=377632/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=0.05
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963600 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200338 s]
/proc/loadavg: 0.90 0.95 0.97 2/60 25575
/proc/meminfo: memFree=377632/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=0.05
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963600 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300322 s]
/proc/loadavg: 0.90 0.95 0.97 2/60 25575
/proc/meminfo: memFree=377632/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=0.05
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963600 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700241 s]
/proc/loadavg: 0.90 0.95 0.97 2/60 25575
/proc/meminfo: memFree=377632/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=0.05
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963600 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.90 0.95 0.97 2/62 25591
/proc/meminfo: memFree=342392/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=0.05
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963600 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25591] ppid=25575 vsize=51500 CPUtime=1.41
/proc/25591/stat : 25591 (cudf2lp) R 25575 25575 32685 0 -1 4202496 14353 0 0 0 136 5 0 0 20 0 1 0 41901011 52736000 10954 18446744073709551615 4194304 5690517 140737422982496 140737422980136 4951958 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/25591/statm: 12875 10954 160 366 0 12506 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 60712

[startup+3.10034 s]
/proc/loadavg: 0.90 0.95 0.97 2/62 25591
/proc/meminfo: memFree=309136/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=0.05
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 733 3622 0 0 0 0 4 1 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963600 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25591] ppid=25575 vsize=78192 CPUtime=3.01
/proc/25591/stat : 25591 (cudf2lp) R 25575 25575 32685 0 -1 4202496 25441 0 0 0 285 16 0 0 20 0 1 0 41901011 80068608 19275 18446744073709551615 4194304 5690517 140737422982496 140737422979832 4956281 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/25591/statm: 19548 19275 174 366 0 19179 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 87404

[startup+6.30032 s]
/proc/loadavg: 0.99 0.97 0.98 2/62 25592
/proc/meminfo: memFree=245004/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=3.14
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 757 29065 0 0 0 0 295 19 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963600 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25592] ppid=25575 vsize=158464 CPUtime=3.08
/proc/25592/stat : 25592 (gringo) R 25575 25575 32685 0 -1 4202496 38766 0 0 0 287 21 0 0 20 0 1 0 41901326 162267136 34097 18446744073709551615 4194304 6531320 140736960337184 140736960334168 5507455 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/25592/statm: 39616 34097 282 571 0 39037 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 167676

[startup+12.7004 s]
/proc/loadavg: 1.07 0.99 0.98 2/63 25597
/proc/meminfo: memFree=267556/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=10.7
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 794 138008 0 0 0 0 994 76 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963008 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25596] ppid=25575 vsize=141536 CPUtime=1.68
/proc/25596/stat : 25596 (clasp) R 25575 25575 32685 0 -1 4202496 41259 0 0 0 153 15 0 0 20 0 1 0 41902104 144932864 34801 18446744073709551615 4194304 6238623 140736208725872 140736208723568 4372100 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/25596/statm: 35384 34801 263 500 0 34881 0
[pid=25597] ppid=25575 vsize=22040 CPUtime=0.02
/proc/25597/stat : 25597 (parse.py) S 25575 25575 32685 0 -1 4202496 1317 0 0 0 1 1 0 0 20 0 1 0 41902104 22568960 1127 18446744073709551615 4194304 6642060 140734446925088 140734446923448 140607546558240 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25597/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.4
Current children cumulated vsize (KiB) 172788

[startup+25.5004 s]
/proc/loadavg: 1.05 0.99 0.98 2/63 25597
/proc/meminfo: memFree=268300/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=10.7
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 794 138008 0 0 0 0 994 76 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963008 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25596] ppid=25575 vsize=141536 CPUtime=14.38
/proc/25596/stat : 25596 (clasp) R 25575 25575 32685 0 -1 4202496 41492 0 0 0 1423 15 0 0 20 0 1 0 41902104 144932864 35034 18446744073709551615 4194304 6238623 140736208725872 140736208722896 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/25596/statm: 35384 35034 263 500 0 34881 0
[pid=25597] ppid=25575 vsize=22040 CPUtime=0.02
/proc/25597/stat : 25597 (parse.py) S 25575 25575 32685 0 -1 4202496 1317 0 0 0 1 1 0 0 20 0 1 0 41902104 22568960 1127 18446744073709551615 4194304 6642060 140734446925088 140734446923448 140607546558240 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25597/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 25.1
Current children cumulated vsize (KiB) 172788

[startup+51.1003 s]
/proc/loadavg: 1.03 0.99 0.98 2/63 25597
/proc/meminfo: memFree=163272/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=10.7
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 794 138008 0 0 0 0 994 76 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963008 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25596] ppid=25575 vsize=258236 CPUtime=39.82
/proc/25596/stat : 25596 (clasp) R 25575 25575 32685 0 -1 4202496 69245 0 0 0 3957 25 0 0 20 0 1 0 41902104 264433664 62787 18446744073709551615 4194304 6238623 140736208725872 140736208722424 4302400 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/25596/statm: 64559 62787 263 500 0 64056 0
[pid=25597] ppid=25575 vsize=22040 CPUtime=0.02
/proc/25597/stat : 25597 (parse.py) S 25575 25575 32685 0 -1 4202496 1317 0 0 0 1 1 0 0 20 0 1 0 41902104 22568960 1127 18446744073709551615 4194304 6642060 140734446925088 140734446923448 140607546558240 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25597/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 50.54
Current children cumulated vsize (KiB) 289488

[startup+102.3 s]
/proc/loadavg: 1.01 0.99 0.98 2/63 25597
/proc/meminfo: memFree=19060/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=10.7
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 794 138008 0 0 0 0 994 76 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963008 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25596] ppid=25575 vsize=395892 CPUtime=90.74
/proc/25596/stat : 25596 (clasp) R 25575 25575 32685 0 -1 4202496 103670 0 0 0 9035 39 0 0 20 0 1 0 41902104 405393408 97212 18446744073709551615 4194304 6238623 140736208725872 140736208722424 4409920 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/25596/statm: 98973 97212 263 500 0 98470 0
[pid=25597] ppid=25575 vsize=22040 CPUtime=0.02
/proc/25597/stat : 25597 (parse.py) S 25575 25575 32685 0 -1 4202496 1317 0 0 0 1 1 0 0 20 0 1 0 41902104 22568960 1127 18446744073709551615 4194304 6642060 140734446925088 140734446923448 140607546558240 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25597/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 101.46
Current children cumulated vsize (KiB) 427144

[startup+162.3 s]
/proc/loadavg: 1.00 0.99 0.98 2/63 25597
/proc/meminfo: memFree=9848/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=10.7
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 794 138008 0 0 0 0 994 76 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963008 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25596] ppid=25575 vsize=531248 CPUtime=150.26
/proc/25596/stat : 25596 (clasp) R 25575 25575 32685 0 -1 4202496 135215 0 0 0 14976 50 0 0 20 0 1 0 41902104 543997952 128757 18446744073709551615 4194304 6238623 140736208725872 140736208722896 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/25596/statm: 132812 128757 263 500 0 132309 0
[pid=25597] ppid=25575 vsize=22040 CPUtime=0.02
/proc/25597/stat : 25597 (parse.py) S 25575 25575 32685 0 -1 4202496 1317 0 0 0 1 1 0 0 20 0 1 0 41902104 22568960 1127 18446744073709551615 4194304 6642060 140734446925088 140734446923448 140607546558240 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25597/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 160.98
Current children cumulated vsize (KiB) 562500

[startup+222.303 s]
/proc/loadavg: 1.00 0.99 0.98 2/63 25605
/proc/meminfo: memFree=9724/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=10.7
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 794 138008 0 0 0 0 994 76 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963008 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25596] ppid=25575 vsize=533672 CPUtime=209.92
/proc/25596/stat : 25596 (clasp) R 25575 25575 32685 0 -1 4202496 135846 0 0 0 20942 50 0 0 20 0 1 0 41902104 546480128 129388 18446744073709551615 4194304 6238623 140736208725872 140736208722896 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/25596/statm: 133418 129388 263 500 0 132915 0
[pid=25597] ppid=25575 vsize=22040 CPUtime=0.02
/proc/25597/stat : 25597 (parse.py) S 25575 25575 32685 0 -1 4202496 1317 0 0 0 1 1 0 0 20 0 1 0 41902104 22568960 1127 18446744073709551615 4194304 6642060 140734446925088 140734446923448 140607546558240 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25597/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 220.64
Current children cumulated vsize (KiB) 564924

[startup+282.3 s]
/proc/loadavg: 1.00 0.99 0.98 2/63 25605
/proc/meminfo: memFree=10096/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=10.7
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 794 138008 0 0 0 0 994 76 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963008 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25596] ppid=25575 vsize=536216 CPUtime=269.59
/proc/25596/stat : 25596 (clasp) R 25575 25575 32685 0 -1 4202496 137104 0 0 0 26908 51 0 0 20 0 1 0 41902104 549085184 130646 18446744073709551615 4194304 6238623 140736208725872 140736208722424 4421834 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/25596/statm: 134054 130646 263 500 0 133551 0
[pid=25597] ppid=25575 vsize=22040 CPUtime=0.02
/proc/25597/stat : 25597 (parse.py) S 25575 25575 32685 0 -1 4202496 1317 0 0 0 1 1 0 0 20 0 1 0 41902104 22568960 1127 18446744073709551615 4194304 6642060 140734446925088 140734446923448 140607546558240 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25597/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 280.31
Current children cumulated vsize (KiB) 567468



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.1 s]
/proc/loadavg: 1.00 0.99 0.98 2/63 25605
/proc/meminfo: memFree=9476/1022884 swapFree=0/0
[pid=25575] ppid=25574 vsize=9212 CPUtime=10.7
/proc/25575/stat : 25575 (aspcud-full) S 25574 25575 32685 0 -1 4202496 794 138008 0 0 0 0 994 76 20 0 1 0 41901007 9433088 365 18446744073709551615 4194304 5129932 140733237964944 140733237963008 140491282977886 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/25575/statm: 2303 365 303 229 0 63 0
[pid=25596] ppid=25575 vsize=538340 CPUtime=289.28
/proc/25596/stat : 25596 (clasp) R 25575 25575 32685 0 -1 4202496 137647 0 0 0 28877 51 0 0 20 0 1 0 41902104 551260160 131189 18446744073709551615 4194304 6238623 140736208725872 140736208722896 4330914 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/25596/statm: 134585 131189 263 500 0 134082 0
[pid=25597] ppid=25575 vsize=22040 CPUtime=0.02
/proc/25597/stat : 25597 (parse.py) S 25575 25575 32685 0 -1 4202496 1317 0 0 0 1 1 0 0 20 0 1 0 41902104 22568960 1127 18446744073709551615 4194304 6642060 140734446925088 140734446923448 140607546558240 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/25597/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 300
Current children cumulated vsize (KiB) 569592

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.169
CPU time (s): 300.095
CPU user time (s): 298.743
CPU system time (s): 1.35208
CPU usage (%): 99.3135
Max. virtual memory (cumulated for all children) (KiB): 569592

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.743
system time used= 1.35208
maximum resident set size= 524800
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 278111
page faults= 0
swaps= 0
block input operations= 43864
block output operations= 46872
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 85
involuntary context switches= 4700

runsolver used 0.620038 second user time and 1.08407 second system time

The end