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/rand943.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/install/rand943.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/install/rand943.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.86 0.97 0.98 2/59 4816
/proc/meminfo: memFree=361588/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=3152 CPUtime=0
/proc/4816/stat : 4816 (runsolver) R 4815 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115550295 3227648 32 18446744073709551615 134512640 134586868 4289294848 4289292896 4152112176 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/4816/statm: 788 32 0 19 0 73 0

[startup+0.173656 s]
/proc/loadavg: 0.86 0.97 0.98 2/59 4816
/proc/meminfo: memFree=361588/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=8116 CPUtime=0.14
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 1770 0 0 0 13 1 0 0 20 0 1 0 115550295 8310784 1693 18446744073709551615 4194304 5895655 140735815251136 140735815247048 4347320 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/4816/statm: 2029 1693 149 416 0 1610 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 8116

[startup+0.200348 s]
/proc/loadavg: 0.86 0.97 0.98 2/59 4816
/proc/meminfo: memFree=361588/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=9104 CPUtime=0.16
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 2019 0 0 0 15 1 0 0 20 0 1 0 115550295 9322496 1942 18446744073709551615 4194304 5895655 140735815251136 140735815247048 4346904 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/4816/statm: 2276 1942 149 416 0 1857 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 9104

[startup+0.300338 s]
/proc/loadavg: 0.86 0.97 0.98 2/59 4816
/proc/meminfo: memFree=361588/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=12752 CPUtime=0.26
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 2915 0 0 0 25 1 0 0 20 0 1 0 115550295 13058048 2838 18446744073709551615 4194304 5895655 140735815251136 140735815247048 5067965 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/4816/statm: 3188 2838 149 416 0 2769 0
Current children cumulated CPU time (s) 0.26
Current children cumulated vsize (KiB) 12752

[startup+0.70024 s]
/proc/loadavg: 0.86 0.97 0.98 2/59 4816
/proc/meminfo: memFree=361588/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=25416 CPUtime=0.64
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 6137 0 0 0 60 4 0 0 20 0 1 0 115550295 26025984 6011 18446744073709551615 4194304 5895655 140735815251136 140735815247048 4346981 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/4816/statm: 6354 6011 149 416 0 5935 0
Current children cumulated CPU time (s) 0.64
Current children cumulated vsize (KiB) 25416

[startup+1.50023 s]
/proc/loadavg: 0.87 0.97 0.98 2/60 4817
/proc/meminfo: memFree=311476/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=48080 CPUtime=1.43
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 11851 0 0 0 138 5 0 0 20 0 1 0 115550295 49233920 11676 18446744073709551615 4194304 5895655 140735815251136 140735815247048 4347320 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/4816/statm: 12020 11676 149 416 0 11601 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 48080

[startup+3.10028 s]
/proc/loadavg: 0.87 0.97 0.98 2/60 4817
/proc/meminfo: memFree=267084/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=104816 CPUtime=3.01
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 27992 0 0 0 290 11 0 0 20 0 1 0 115550295 107331584 24502 18446744073709551615 4194304 5895655 140735815251136 140735815245992 4448385 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/4816/statm: 26204 24502 195 416 0 25785 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 104816

[startup+6.30021 s]
/proc/loadavg: 0.87 0.97 0.98 2/60 4817
/proc/meminfo: memFree=227512/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=108604 CPUtime=6.19
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 28702 0 0 0 607 12 0 0 20 0 1 0 115550295 111210496 25110 18446744073709551615 4194304 5895655 140735815251136 140735815245992 4436292 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/4816/statm: 27151 25110 195 416 0 26732 0
Current children cumulated CPU time (s) 6.19
Current children cumulated vsize (KiB) 108604

[startup+12.7002 s]
/proc/loadavg: 0.89 0.97 0.98 2/60 4817
/proc/meminfo: memFree=227264/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=108604 CPUtime=12.54
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 28729 0 0 0 1241 13 0 0 20 0 1 0 115550295 111210496 25134 18446744073709551615 4194304 5895655 140735815251136 140735815245992 5073386 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/4816/statm: 27151 25134 195 416 0 26732 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 108604

[startup+25.5003 s]
/proc/loadavg: 0.91 0.97 0.98 2/60 4817
/proc/meminfo: memFree=227140/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=108604 CPUtime=25.23
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 28766 0 0 0 2509 14 0 0 20 0 1 0 115550295 111210496 25167 18446744073709551615 4194304 5895655 140735815251136 140735815245992 4451297 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/4816/statm: 27151 25167 195 416 0 26732 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 108604

[startup+51.1003 s]
/proc/loadavg: 0.94 0.97 0.98 2/60 4817
/proc/meminfo: memFree=225404/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=110364 CPUtime=50.61
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 29312 0 0 0 5043 18 0 0 20 0 1 0 115550295 113012736 25597 18446744073709551615 4194304 5895655 140735815251136 140735815245992 4452673 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/4816/statm: 27591 25597 195 416 0 27172 0
Current children cumulated CPU time (s) 50.61
Current children cumulated vsize (KiB) 110364

[startup+102.3 s]
/proc/loadavg: 0.97 0.97 0.98 2/60 4817
/proc/meminfo: memFree=217592/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=116528 CPUtime=101.34
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 369896 0 0 0 9974 160 0 0 20 0 1 0 115550295 119324672 27495 18446744073709551615 4194304 5895655 140735815251136 140735815245992 5081999 0 0 16781316 16929 0 0 0 17 0 0 0 12 0 0
/proc/4816/statm: 29132 27495 195 416 0 28713 0
Current children cumulated CPU time (s) 101.34
Current children cumulated vsize (KiB) 116528



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.5 s]
/proc/loadavg: 0.99 0.97 0.98 2/60 4817
/proc/meminfo: memFree=202712/1022884 swapFree=0/0
[pid=4816] ppid=4815 vsize=131856 CPUtime=150.08
/proc/4816/stat : 4816 (cudf_fumax_bu-0) R 4815 4816 1750 0 -1 4202496 373642 0 0 0 14843 165 0 0 20 0 1 0 115550295 135020544 31117 18446744073709551615 4194304 5895655 140735815251136 140735815245992 4436174 0 0 16781316 16929 0 0 0 17 0 0 0 22 0 0
/proc/4816/statm: 32964 31117 196 416 0 32545 0
Current children cumulated CPU time (s) 150.08
Current children cumulated vsize (KiB) 131856

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.564
CPU time (s): 150.153
CPU user time (s): 148.481
CPU system time (s): 1.6721
CPU usage (%): 99.0693
Max. virtual memory (cumulated for all children) (KiB): 131856

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.481
system time used= 1.6721
maximum resident set size= 124468
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 373644
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 488
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 86
involuntary context switches= 17161

runsolver used 0.316019 second user time and 0.464029 second system time

The end