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/install/rand446.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/install/rand446.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/install/rand446.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.87 1.02 1.06 2/64 5041
/proc/meminfo: memFree=325536/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=2148 CPUtime=0
/proc/5041/stat : 5041 (cudf_fumax_bu-0) D 5040 5041 1745 0 -1 4202496 246 0 0 0 0 0 0 0 20 0 1 0 115548477 2199552 169 18446744073709551615 4194304 5895655 140734911790608 140734911786520 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/5041/statm: 537 169 135 416 0 118 0

[startup+0.159324 s]
/proc/loadavg: 0.87 1.02 1.06 2/64 5041
/proc/meminfo: memFree=325536/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=7324 CPUtime=0.11
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 1570 0 0 0 11 0 0 0 20 0 1 0 115548477 7499776 1493 18446744073709551615 4194304 5895655 140734911790608 140734911786520 4346908 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5041/statm: 1831 1493 149 416 0 1412 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 7324

[startup+0.200345 s]
/proc/loadavg: 0.87 1.02 1.06 2/64 5041
/proc/meminfo: memFree=325536/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=8972 CPUtime=0.16
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 1961 0 0 0 15 1 0 0 20 0 1 0 115548477 9187328 1884 18446744073709551615 4194304 5895655 140734911790608 140734911786520 4410140 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5041/statm: 2243 1884 149 416 0 1824 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 8972

[startup+0.3003 s]
/proc/loadavg: 0.87 1.02 1.06 2/64 5041
/proc/meminfo: memFree=325536/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=12488 CPUtime=0.26
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 2860 0 0 0 24 2 0 0 20 0 1 0 115548477 12787712 2783 18446744073709551615 4194304 5895655 140734911790608 140734911786520 4346784 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5041/statm: 3122 2783 149 416 0 2703 0
Current children cumulated CPU time (s) 0.26
Current children cumulated vsize (KiB) 12488

[startup+0.700233 s]
/proc/loadavg: 0.87 1.02 1.06 2/64 5041
/proc/meminfo: memFree=325536/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=25548 CPUtime=0.63
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 6177 0 0 0 58 5 0 0 20 0 1 0 115548477 26161152 6051 18446744073709551615 4194304 5895655 140734911790608 140734911786520 4347026 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/5041/statm: 6387 6051 149 416 0 5968 0
Current children cumulated CPU time (s) 0.63
Current children cumulated vsize (KiB) 25548

[startup+1.50031 s]
/proc/loadavg: 0.87 1.02 1.06 2/65 5042
/proc/meminfo: memFree=275516/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=46496 CPUtime=1.31
/proc/5041/stat : 5041 (cudf_fumax_bu-0) D 5040 5041 1745 0 -1 4202496 11441 0 0 0 121 10 0 0 20 0 1 0 115548477 47611904 11266 18446744073709551615 4194304 5895655 140734911790608 140734911786520 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/5041/statm: 11624 11266 149 416 0 11205 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 46496

[startup+3.10025 s]
/proc/loadavg: 0.87 1.02 1.06 2/65 5042
/proc/meminfo: memFree=260496/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=70640 CPUtime=2.21
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 17600 0 0 0 204 17 0 0 20 0 1 0 115548477 72335360 17328 18446744073709551615 4194304 5895655 140734911790608 140734911786520 5082018 0 0 16781316 16929 0 0 0 17 0 0 0 85 0 0
/proc/5041/statm: 17660 17328 149 416 0 17241 0
Current children cumulated CPU time (s) 2.21
Current children cumulated vsize (KiB) 70640
heavy processes:

[startup+6.30022 s]
/proc/loadavg: 0.88 1.02 1.06 2/65 5042
/proc/meminfo: memFree=193504/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=105248 CPUtime=5.37
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 26434 0 0 0 517 20 0 0 20 0 1 0 115548477 107773952 24578 18446744073709551615 4194304 5895655 140734911790608 140734911785464 4473075 0 0 16781316 16929 0 0 0 17 0 0 0 86 0 0
/proc/5041/statm: 26312 24578 195 416 0 25893 0
Current children cumulated CPU time (s) 5.37
Current children cumulated vsize (KiB) 105248

[startup+12.7002 s]
/proc/loadavg: 0.89 1.02 1.06 2/65 5042
/proc/meminfo: memFree=192636/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=106260 CPUtime=11.69
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 26686 0 0 0 1148 21 0 0 20 0 1 0 115548477 108810240 24769 18446744073709551615 4194304 5895655 140734911790608 140734911785464 4452015 0 0 16781316 16929 0 0 0 17 0 0 0 90 0 0
/proc/5041/statm: 26565 24769 195 416 0 26146 0
Current children cumulated CPU time (s) 11.69
Current children cumulated vsize (KiB) 106260

[startup+25.5003 s]
/proc/loadavg: 0.91 1.02 1.05 2/65 5042
/proc/meminfo: memFree=192016/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=106740 CPUtime=24.36
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 26871 0 0 0 2414 22 0 0 20 0 1 0 115548477 109301760 24905 18446744073709551615 4194304 5895655 140734911790608 140734911785464 5093969 0 0 16781316 16929 0 0 0 17 0 0 0 93 0 0
/proc/5041/statm: 26685 24905 195 416 0 26266 0
Current children cumulated CPU time (s) 24.36
Current children cumulated vsize (KiB) 106740

[startup+51.1003 s]
/proc/loadavg: 0.94 1.02 1.05 2/65 5042
/proc/meminfo: memFree=189536/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=109332 CPUtime=49.71
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 27657 0 0 0 4945 26 0 0 20 0 1 0 115548477 111955968 25515 18446744073709551615 4194304 5895655 140734911790608 140734911785464 4452627 0 0 16781316 16929 0 0 0 17 0 0 0 98 0 0
/proc/5041/statm: 27333 25515 195 416 0 26914 0
Current children cumulated CPU time (s) 49.71
Current children cumulated vsize (KiB) 109332

[startup+102.3 s]
/proc/loadavg: 0.97 1.01 1.05 2/65 5042
/proc/meminfo: memFree=172912/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=124624 CPUtime=100.42
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 170308 0 0 0 9957 85 0 0 20 0 1 0 115548477 127614976 29624 18446744073709551615 4194304 5895655 140734911790608 140734911785464 5130366 0 0 16781316 16929 0 0 0 17 0 0 0 110 0 0
/proc/5041/statm: 31156 29624 195 416 0 30737 0
Current children cumulated CPU time (s) 100.42
Current children cumulated vsize (KiB) 124624



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+152.5 s]
/proc/loadavg: 0.99 1.01 1.04 2/65 5042
/proc/meminfo: memFree=152080/1022884 swapFree=0/0
[pid=5041] ppid=5040 vsize=145296 CPUtime=150.09
/proc/5041/stat : 5041 (cudf_fumax_bu-0) R 5040 5041 1745 0 -1 4202496 267693 0 0 0 14879 130 0 0 20 0 1 0 115548477 148783104 34736 18446744073709551615 4194304 5895655 140734911790608 140734911785464 4454155 0 0 16781316 16929 0 0 0 17 0 0 0 121 0 0
/proc/5041/statm: 36324 34736 196 416 0 35905 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 145296

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): 152.572
CPU time (s): 150.169
CPU user time (s): 148.845
CPU system time (s): 1.32408
CPU usage (%): 98.4253
Max. virtual memory (cumulated for all children) (KiB): 145300

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.845
system time used= 1.32408
maximum resident set size= 138944
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 267695
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 464
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 91
involuntary context switches= 17122

runsolver used 0.272017 second user time and 0.528033 second system time

The end