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/cudf_fumax_bu-0.1/paranoid-size/real/fe523ea6-9b1b-11df-bc37-00163e46d37a.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/fe523ea6-9b1b-11df-bc37-00163e46d37a.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/real/fe523ea6-9b1b-11df-bc37-00163e46d37a.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

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.85 0.93 0.97 2/64 5383
/proc/meminfo: memFree=154356/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=2008 CPUtime=0
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 223 0 0 0 0 0 0 0 20 0 1 0 115684890 2056192 146 18446744073709551615 4194304 5895655 140733606499264 140733606497368 4978299 0 0 16781316 1 0 0 0 17 0 0 0 0 0 0
/proc/5383/statm: 502 146 122 416 0 83 0

[startup+0.177272 s]
/proc/loadavg: 0.85 0.93 0.97 2/64 5383
/proc/meminfo: memFree=154356/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=9952 CPUtime=0.16
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 2204 0 0 0 16 0 0 0 20 0 1 0 115684890 10190848 2127 18446744073709551615 4194304 5895655 140733606499264 140733606495176 4196016 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/5383/statm: 2488 2127 149 416 0 2069 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 9952

[startup+0.200326 s]
/proc/loadavg: 0.85 0.93 0.97 2/64 5383
/proc/meminfo: memFree=154356/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=10700 CPUtime=0.19
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 2421 0 0 0 18 1 0 0 20 0 1 0 115684890 10956800 2344 18446744073709551615 4194304 5895655 140733606499264 140733606495176 4346823 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/5383/statm: 2675 2344 149 416 0 2256 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 10700

[startup+0.300314 s]
/proc/loadavg: 0.85 0.93 0.97 2/64 5383
/proc/meminfo: memFree=154356/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=14660 CPUtime=0.29
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 3382 0 0 0 28 1 0 0 20 0 1 0 115684890 15011840 3305 18446744073709551615 4194304 5895655 140733606499264 140733606495016 5107398 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/5383/statm: 3665 3305 149 416 0 3246 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 14660

[startup+0.700301 s]
/proc/loadavg: 0.85 0.93 0.97 2/64 5383
/proc/meminfo: memFree=154356/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=28648 CPUtime=0.69
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 6942 0 0 0 65 4 0 0 20 0 1 0 115684890 29335552 6816 18446744073709551615 4194304 5895655 140733606499264 140733606495176 4346750 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/5383/statm: 7162 6816 149 416 0 6743 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 28648

[startup+1.50025 s]
/proc/loadavg: 0.86 0.93 0.97 2/65 5384
/proc/meminfo: memFree=115280/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=62400 CPUtime=1.48
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 14765 0 0 0 140 8 0 0 20 0 1 0 115684890 63897600 14113 18446744073709551615 4194304 5895655 140733606499264 140733606494120 5085143 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/5383/statm: 15600 14113 195 416 0 15181 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 62400

[startup+3.10025 s]
/proc/loadavg: 0.86 0.93 0.97 2/65 5384
/proc/meminfo: memFree=98416/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=62400 CPUtime=3.06
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 14801 0 0 0 298 8 0 0 20 0 1 0 115684890 63897600 14146 18446744073709551615 4194304 5895655 140733606499264 140733606494120 5094260 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/5383/statm: 15600 14146 195 416 0 15181 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 62400

[startup+6.30023 s]
/proc/loadavg: 0.86 0.93 0.97 2/65 5384
/proc/meminfo: memFree=98292/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=62400 CPUtime=6.21
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 14829 0 0 0 611 10 0 0 20 0 1 0 115684890 63897600 14173 18446744073709551615 4194304 5895655 140733606499264 140733606494120 5093799 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/5383/statm: 15600 14173 195 416 0 15181 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 62400

[startup+12.7002 s]
/proc/loadavg: 0.88 0.94 0.97 2/65 5384
/proc/meminfo: memFree=96680/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=63024 CPUtime=12.55
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 15287 0 0 0 1243 12 0 0 20 0 1 0 115684890 64536576 14538 18446744073709551615 4194304 5895655 140733606499264 140733606494120 4436040 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5383/statm: 15756 14538 195 416 0 15337 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 63024

[startup+25.5003 s]
/proc/loadavg: 0.90 0.94 0.97 2/65 5384
/proc/meminfo: memFree=94200/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=64624 CPUtime=25.23
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 15905 0 0 0 2506 17 0 0 20 0 1 0 115684890 66174976 15151 18446744073709551615 4194304 5895655 140733606499264 140733606494120 5081866 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5383/statm: 16156 15151 195 416 0 15737 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 64624

[startup+51.1002 s]
/proc/loadavg: 0.93 0.94 0.97 2/65 5384
/proc/meminfo: memFree=10128/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=167592 CPUtime=50.6
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 49480 0 0 0 5021 39 0 0 20 0 1 0 115684890 171614208 37084 18446744073709551615 4194304 5895655 140733606499264 140733606493224 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/5383/statm: 41898 37084 207 416 0 41479 0
Current children cumulated CPU time (s) 50.6
Current children cumulated vsize (KiB) 167592

[startup+102.3 s]
/proc/loadavg: 0.97 0.95 0.97 2/65 5384
/proc/meminfo: memFree=86760/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=136972 CPUtime=101.41
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 97900 0 0 0 10047 94 0 0 20 0 1 0 115684890 140259328 29023 18446744073709551615 4194304 5895655 140733606499264 140733606493224 4446984 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/5383/statm: 34243 29023 207 416 0 33824 0
Current children cumulated CPU time (s) 101.41
Current children cumulated vsize (KiB) 136972



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.3 s]
/proc/loadavg: 0.99 0.95 0.97 2/65 5384
/proc/meminfo: memFree=34556/1022884 swapFree=0/0
[pid=5383] ppid=5382 vsize=217880 CPUtime=150.07
/proc/5383/stat : 5383 (cudf_fumax_bu-0) R 5382 5383 1745 0 -1 4202496 129958 0 0 0 14877 130 0 0 20 0 1 0 115684890 223109120 41962 18446744073709551615 4194304 5895655 140733606499264 140733606493224 4447009 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/5383/statm: 54470 41962 207 416 0 54051 0
Current children cumulated CPU time (s) 150.07
Current children cumulated vsize (KiB) 217880

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): 151.35
CPU time (s): 150.121
CPU user time (s): 148.805
CPU system time (s): 1.31608
CPU usage (%): 99.1883
Max. virtual memory (cumulated for all children) (KiB): 217880

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.805
system time used= 1.31608
maximum resident set size= 192532
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 129960
page faults= 0
swaps= 0
block input operations= 0
block output operations= 296
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 13
involuntary context switches= 17139

runsolver used 0.276017 second user time and 0.48003 second system time

The end