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/rand308.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/install/rand308.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/install/rand308.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: 1.57 1.42 1.16 2/64 5021
/proc/meminfo: memFree=431504/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=3152 CPUtime=0
/proc/5021/stat : 5021 (runsolver) D 5020 5021 1745 0 -1 4202560 75 0 0 0 0 0 0 0 20 0 1 0 115498259 3227648 97 18446744073709551615 134512640 134586868 4293850416 4293848464 4151776304 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5021/statm: 788 97 64 19 0 73 0

[startup+0.136341 s]
/proc/loadavg: 1.57 1.42 1.16 2/64 5021
/proc/meminfo: memFree=431504/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=4656 CPUtime=0.05
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 888 0 15 0 5 0 0 0 20 0 1 0 115498259 4767744 825 18446744073709551615 4194304 5895655 140735157928960 140735157924872 4347094 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/5021/statm: 1164 825 146 416 0 745 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 4656

[startup+0.20031 s]
/proc/loadavg: 1.57 1.42 1.16 2/64 5021
/proc/meminfo: memFree=431504/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=7456 CPUtime=0.11
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 1570 0 15 0 10 1 0 0 20 0 1 0 115498259 7634944 1507 18446744073709551615 4194304 5895655 140735157928960 140735157924872 5085989 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/5021/statm: 1864 1507 149 416 0 1445 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 7456

[startup+0.300298 s]
/proc/loadavg: 1.57 1.42 1.16 2/64 5021
/proc/meminfo: memFree=431504/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=11300 CPUtime=0.22
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 2536 0 15 0 20 2 0 0 20 0 1 0 115498259 11571200 2473 18446744073709551615 4194304 5895655 140735157928960 140735157924872 5299651 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/5021/statm: 2825 2473 149 416 0 2406 0
Current children cumulated CPU time (s) 0.22
Current children cumulated vsize (KiB) 11300

[startup+0.70022 s]
/proc/loadavg: 1.57 1.42 1.16 2/64 5021
/proc/meminfo: memFree=431504/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=25284 CPUtime=0.6
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 6080 0 15 0 56 4 0 0 20 0 1 0 115498259 25890816 5968 18446744073709551615 4194304 5895655 140735157928960 140735157924872 5081845 0 0 16781316 16929 0 0 0 17 0 0 0 8 0 0
/proc/5021/statm: 6321 5968 149 416 0 5902 0
Current children cumulated CPU time (s) 0.6
Current children cumulated vsize (KiB) 25284

[startup+1.50023 s]
/proc/loadavg: 1.52 1.41 1.16 2/65 5022
/proc/meminfo: memFree=378540/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=49136 CPUtime=1.37
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 12085 0 15 0 128 9 0 0 20 0 1 0 115498259 50315264 11924 18446744073709551615 4194304 5895655 140735157928960 140735157924728 4346931 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/5021/statm: 12284 11924 149 416 0 11865 0
Current children cumulated CPU time (s) 1.37
Current children cumulated vsize (KiB) 49136

[startup+3.10026 s]
/proc/loadavg: 1.52 1.41 1.16 2/65 5022
/proc/meminfo: memFree=333776/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=102920 CPUtime=2.93
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 25908 0 16 0 277 16 0 0 20 0 1 0 115498259 105390080 23960 18446744073709551615 4194304 5895655 140735157928960 140735157923816 4452167 0 0 16781316 16929 0 0 0 17 0 0 0 13 0 0
/proc/5021/statm: 25730 23960 195 416 0 25311 0
Current children cumulated CPU time (s) 2.93
Current children cumulated vsize (KiB) 102920

[startup+6.30025 s]
/proc/loadavg: 1.52 1.41 1.16 2/65 5022
/proc/meminfo: memFree=298932/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=105500 CPUtime=6.07
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 26324 0 17 0 591 16 0 0 20 0 1 0 115498259 108032000 24358 18446744073709551615 4194304 5895655 140735157928960 140735157923816 5094686 0 0 16781316 16929 0 0 0 17 0 0 0 16 0 0
/proc/5021/statm: 26375 24358 204 416 0 25956 0
Current children cumulated CPU time (s) 6.07
Current children cumulated vsize (KiB) 105500

[startup+12.7002 s]
/proc/loadavg: 1.44 1.40 1.16 2/65 5022
/proc/meminfo: memFree=298808/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=105500 CPUtime=12.42
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 26337 0 17 0 1226 16 0 0 20 0 1 0 115498259 108032000 24371 18446744073709551615 4194304 5895655 140735157928960 140735157923816 5073325 0 0 16781316 16929 0 0 0 17 0 0 0 16 0 0
/proc/5021/statm: 26375 24371 204 416 0 25956 0
Current children cumulated CPU time (s) 12.42
Current children cumulated vsize (KiB) 105500

[startup+25.5003 s]
/proc/loadavg: 1.37 1.38 1.15 2/65 5022
/proc/meminfo: memFree=297816/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=106516 CPUtime=25.09
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 26613 0 17 0 2492 17 0 0 20 0 1 0 115498259 109072384 24591 18446744073709551615 4194304 5895655 140735157928960 140735157923816 4452480 0 0 16781316 16929 0 0 0 17 0 0 0 18 0 0
/proc/5021/statm: 26629 24591 204 416 0 26210 0
Current children cumulated CPU time (s) 25.09
Current children cumulated vsize (KiB) 106516

[startup+51.1003 s]
/proc/loadavg: 1.25 1.35 1.15 2/65 5022
/proc/meminfo: memFree=295584/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=108464 CPUtime=50.48
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 27410 0 17 0 5027 21 0 0 20 0 1 0 115498259 111067136 25199 18446744073709551615 4194304 5895655 140735157928960 140735157923816 4446924 0 0 16781316 16929 0 0 0 17 0 0 0 20 0 0
/proc/5021/statm: 27116 25199 204 416 0 26697 0
Current children cumulated CPU time (s) 50.48
Current children cumulated vsize (KiB) 108464

[startup+102.3 s]
/proc/loadavg: 1.10 1.29 1.14 2/65 5022
/proc/meminfo: memFree=279464/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=124060 CPUtime=101.18
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 107154 0 17 0 10054 64 0 0 20 0 1 0 115498259 127037440 29130 18446744073709551615 4194304 5895655 140735157928960 140735157923816 4470561 0 0 16781316 16929 0 0 0 17 0 0 0 27 0 0
/proc/5021/statm: 31015 29130 204 416 0 30596 0
Current children cumulated CPU time (s) 101.18
Current children cumulated vsize (KiB) 124060



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.7 s]
/proc/loadavg: 1.04 1.24 1.13 2/65 5022
/proc/meminfo: memFree=269420/1022884 swapFree=0/0
[pid=5021] ppid=5020 vsize=132376 CPUtime=150.07
/proc/5021/stat : 5021 (cudf_fumax_bu-0) R 5020 5021 1745 0 -1 4202496 109621 0 17 0 14938 69 0 0 20 0 1 0 115498259 135553024 31586 18446744073709551615 4194304 5895655 140735157928960 140735157923816 4468355 0 0 16781316 16929 0 0 0 17 0 0 0 38 0 0
/proc/5021/statm: 33094 31586 204 416 0 32675 0
Current children cumulated CPU time (s) 150.07
Current children cumulated vsize (KiB) 132376

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.8
CPU time (s): 150.169
CPU user time (s): 149.445
CPU system time (s): 0.724045
CPU usage (%): 98.9259
Max. virtual memory (cumulated for all children) (KiB): 132376

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.445
system time used= 0.724045
maximum resident set size= 126344
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 109623
page faults= 17
swaps= 0
block input operations= 71568
block output operations= 512
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 109
involuntary context switches= 17254

runsolver used 0.284017 second user time and 0.568035 second system time

The end