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 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/install/rand411.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand411.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/install/rand411.cudf.result -sum(solution,installedsize),-count(removed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 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.86 0.92 0.95 2/64 5430
/proc/meminfo: memFree=389248/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9204 CPUtime=0
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 431 0 0 0 0 0 0 0 20 0 1 0 115725449 9424896 332 18446744073709551615 4194304 5129932 140734997124960 140734997122424 140697330796320 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2301 332 272 229 0 61 0

[startup+0.159606 s]
/proc/loadavg: 0.86 0.92 0.95 2/64 5430
/proc/meminfo: memFree=389248/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=0.05
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 737 3609 0 0 0 0 4 1 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123616 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200329 s]
/proc/loadavg: 0.86 0.92 0.95 2/64 5430
/proc/meminfo: memFree=389248/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=0.05
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 737 3609 0 0 0 0 4 1 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123616 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300333 s]
/proc/loadavg: 0.86 0.92 0.95 2/64 5430
/proc/meminfo: memFree=389248/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=0.05
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 737 3609 0 0 0 0 4 1 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123616 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700222 s]
/proc/loadavg: 0.86 0.92 0.95 2/64 5430
/proc/meminfo: memFree=389248/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=0.05
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 737 3609 0 0 0 0 4 1 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123616 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50036 s]
/proc/loadavg: 0.88 0.92 0.95 2/66 5446
/proc/meminfo: memFree=354008/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=0.05
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 737 3609 0 0 0 0 4 1 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123616 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
[pid=5446] ppid=5430 vsize=57336 CPUtime=1.43
/proc/5446/stat : 5446 (cudf2lp) R 5430 5430 1745 0 -1 4202496 14152 0 0 0 137 6 0 0 20 0 1 0 115725453 58712064 12418 18446744073709551615 4194304 5690517 140735299367584 140735299363736 4296817 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/5446/statm: 14334 12418 160 366 0 13965 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 66548

[startup+3.10034 s]
/proc/loadavg: 0.88 0.92 0.95 2/66 5446
/proc/meminfo: memFree=322140/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=0.05
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 737 3609 0 0 0 0 4 1 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123616 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
[pid=5446] ppid=5430 vsize=93028 CPUtime=3.01
/proc/5446/stat : 5446 (cudf2lp) R 5430 5430 1745 0 -1 4202496 26540 0 0 0 291 10 0 0 20 0 1 0 115725453 95260672 19812 18446744073709551615 4194304 5690517 140735299367584 140735299365224 4293575 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/5446/statm: 23257 19812 160 366 0 22888 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 102240

[startup+6.30033 s]
/proc/loadavg: 0.88 0.92 0.95 2/66 5447
/proc/meminfo: memFree=330324/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=4.96
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 763 42930 0 0 0 0 470 26 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123616 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
[pid=5447] ppid=5430 vsize=39856 CPUtime=1.27
/proc/5447/stat : 5447 (gringo) R 5430 5430 1745 0 -1 4202496 11128 0 0 0 118 9 0 0 20 0 1 0 115725951 40812544 7994 18446744073709551615 4194304 6531320 140734647770912 140734647766728 5462564 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/5447/statm: 9964 7994 259 571 0 9385 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 49068

[startup+12.7002 s]
/proc/loadavg: 0.89 0.93 0.95 2/66 5447
/proc/meminfo: memFree=38188/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=12.14
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 804 144455 0 0 0 0 1132 82 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123024 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 12.14
Current children cumulated vsize (KiB) 9212

[startup+25.5004 s]
/proc/loadavg: 0.91 0.93 0.95 2/67 5449
/proc/meminfo: memFree=245632/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=12.14
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 804 144455 0 0 0 0 1132 82 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123024 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
[pid=5448] ppid=5430 vsize=132164 CPUtime=12.99
/proc/5448/stat : 5448 (clasp) R 5430 5430 1745 0 -1 4202496 38689 0 0 0 1280 19 0 0 20 0 1 0 115726684 135335936 32715 18446744073709551615 4194304 6238623 140735702746384 140735702743408 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5448/statm: 33041 32715 263 500 0 32538 0
[pid=5449] ppid=5430 vsize=22040 CPUtime=0.02
/proc/5449/stat : 5449 (parse.py) S 5430 5430 1745 0 -1 4202496 1320 0 0 0 0 2 0 0 20 0 1 0 115726684 22568960 1129 18446744073709551615 4194304 6642060 140734795247136 140734795245496 140480686114592 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5449/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 25.15
Current children cumulated vsize (KiB) 163416

[startup+51.1003 s]
/proc/loadavg: 1.02 0.95 0.95 2/67 5449
/proc/meminfo: memFree=245508/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=12.14
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 804 144455 0 0 0 0 1132 82 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123024 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
[pid=5448] ppid=5430 vsize=132164 CPUtime=38.36
/proc/5448/stat : 5448 (clasp) R 5430 5430 1745 0 -1 4202496 38689 0 0 0 3817 19 0 0 20 0 1 0 115726684 135335936 32715 18446744073709551615 4194304 6238623 140735702746384 140735702743408 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5448/statm: 33041 32715 263 500 0 32538 0
[pid=5449] ppid=5430 vsize=22040 CPUtime=0.02
/proc/5449/stat : 5449 (parse.py) S 5430 5430 1745 0 -1 4202496 1320 0 0 0 0 2 0 0 20 0 1 0 115726684 22568960 1129 18446744073709551615 4194304 6642060 140734795247136 140734795245496 140480686114592 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5449/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 50.52
Current children cumulated vsize (KiB) 163416

[startup+102.3 s]
/proc/loadavg: 1.01 0.95 0.95 2/67 5449
/proc/meminfo: memFree=175820/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=12.14
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 804 144455 0 0 0 0 1132 82 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123024 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
[pid=5448] ppid=5430 vsize=201920 CPUtime=89.18
/proc/5448/stat : 5448 (clasp) R 5430 5430 1745 0 -1 4202496 56098 0 0 0 8890 28 0 0 20 0 1 0 115726684 206766080 50124 18446744073709551615 4194304 6238623 140735702746384 140735702742936 4422173 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5448/statm: 50480 50124 263 500 0 49977 0
[pid=5449] ppid=5430 vsize=22040 CPUtime=0.02
/proc/5449/stat : 5449 (parse.py) S 5430 5430 1745 0 -1 4202496 1320 0 0 0 0 2 0 0 20 0 1 0 115726684 22568960 1129 18446744073709551615 4194304 6642060 140734795247136 140734795245496 140480686114592 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5449/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 101.34
Current children cumulated vsize (KiB) 233172



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.4 s]
/proc/loadavg: 1.00 0.96 0.95 2/67 5449
/proc/meminfo: memFree=84680/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=12.14
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 804 144455 0 0 0 0 1132 82 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123024 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
[pid=5448] ppid=5430 vsize=293436 CPUtime=137.92
/proc/5448/stat : 5448 (clasp) R 5430 5430 1745 0 -1 4202496 78801 0 0 0 13754 38 0 0 20 0 1 0 115726684 300478464 72827 18446744073709551615 4194304 6238623 140735702746384 140735702742936 4355605 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5448/statm: 73359 72827 263 500 0 72856 0
[pid=5449] ppid=5430 vsize=22040 CPUtime=0.02
/proc/5449/stat : 5449 (parse.py) S 5430 5430 1745 0 -1 4202496 1320 0 0 0 0 2 0 0 20 0 1 0 115726684 22568960 1129 18446744073709551615 4194304 6642060 140734795247136 140734795245496 140480686114592 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5449/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 150.08
Current children cumulated vsize (KiB) 324688

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+151.4 s]
/proc/loadavg: 1.00 0.96 0.95 2/67 5449
/proc/meminfo: memFree=84680/1022884 swapFree=0/0
[pid=5430] ppid=5429 vsize=9212 CPUtime=12.14
/proc/5430/stat : 5430 (aspcud-basic) S 5429 5430 1745 0 -1 4202496 804 144455 0 0 0 0 1132 82 20 0 1 0 115725449 9433088 365 18446744073709551615 4194304 5129932 140734997124960 140734997123024 140697330652254 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5430/statm: 2303 365 303 229 0 63 0
[pid=5448] ppid=5430 vsize=293436 CPUtime=137.92
/proc/5448/stat : 5448 (clasp) R 5430 5430 1745 0 -1 4202496 78801 0 0 0 13754 38 0 0 20 0 1 0 115726684 300478464 72827 18446744073709551615 4194304 6238623 140735702746384 140735702742936 4355605 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5448/statm: 73359 72827 263 500 0 72856 0
[pid=5449] ppid=5430 vsize=22040 CPUtime=0.02
/proc/5449/stat : 5449 (parse.py) S 5430 5430 1745 0 -1 4202496 1320 0 0 0 0 2 0 0 20 0 1 0 115726684 22568960 1129 18446744073709551615 4194304 6642060 140734795247136 140734795245496 140480686114592 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5449/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 150.08
Current children cumulated vsize (KiB) 324688

Child status: 0
Real time (s): 151.441
CPU time (s): 150.141
CPU user time (s): 148.885
CPU system time (s): 1.25608
CPU usage (%): 99.1417
Max. virtual memory (cumulated for all children) (KiB): 433768

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.885
system time used= 1.25608
maximum resident set size= 368964
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 225681
page faults= 0
swaps= 0
block input operations= 68344
block output operations= 48896
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 64
involuntary context switches= 17250

runsolver used 0.252015 second user time and 0.680042 second system time

The end