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/embedded/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/embedded/install/rand308.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

[startup+0 s]
/proc/loadavg: 0.98 1.15 1.03 2/59 24637
/proc/meminfo: memFree=276480/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=3152 CPUtime=0
/proc/24637/stat : 24637 (runsolver) R 24636 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 116014858 3227648 33 18446744073709551615 134512640 134586868 4288727104 4288725152 4151505968 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/24637/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.129061 s]
/proc/loadavg: 0.98 1.15 1.03 2/59 24637
/proc/meminfo: memFree=276480/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=10508 CPUtime=0.11
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 2368 0 0 0 11 0 0 0 20 0 1 0 116014858 10760192 2290 18446744073709551615 4194304 5895655 140734765069488 140734765065400 5087514 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/24637/statm: 2627 2290 149 416 0 2208 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 10508

[startup+0.200252 s]
/proc/loadavg: 0.98 1.15 1.03 2/59 24637
/proc/meminfo: memFree=276480/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=14600 CPUtime=0.19
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 3395 0 0 0 18 1 0 0 20 0 1 0 116014858 14950400 3317 18446744073709551615 4194304 5895655 140734765069488 140734765065400 4300444 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/24637/statm: 3650 3317 149 416 0 3231 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 14600

[startup+0.300244 s]
/proc/loadavg: 0.98 1.15 1.03 2/59 24637
/proc/meminfo: memFree=276480/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=20268 CPUtime=0.29
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 4846 0 0 0 27 2 0 0 20 0 1 0 116014858 20754432 4719 18446744073709551615 4194304 5895655 140734765069488 140734765065400 4408506 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/24637/statm: 5067 4719 149 416 0 4648 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 20268

[startup+0.700178 s]
/proc/loadavg: 0.98 1.15 1.03 2/59 24637
/proc/meminfo: memFree=276480/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=38180 CPUtime=0.63
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 9359 0 0 0 60 3 0 0 20 0 1 0 116014858 39096320 9183 18446744073709551615 4194304 5895655 140734765069488 140734765065400 4347053 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/24637/statm: 9545 9183 149 416 0 9126 0
Current children cumulated CPU time (s) 0.63
Current children cumulated vsize (KiB) 38180

[startup+1.5003 s]
/proc/loadavg: 0.98 1.15 1.03 2/60 24638
/proc/meminfo: memFree=198104/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=70376 CPUtime=1.36
/proc/24637/stat : 24637 (cudf_fumax_bu-0) D 24636 24637 1733 0 -1 4202496 17528 0 0 0 128 8 0 0 20 0 1 0 116014858 72065024 17255 18446744073709551615 4194304 5895655 140734765069488 140734765065400 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/24637/statm: 17594 17255 149 416 0 17175 0
Current children cumulated CPU time (s) 1.36
Current children cumulated vsize (KiB) 70376

[startup+3.10025 s]
/proc/loadavg: 0.98 1.15 1.03 2/60 24638
/proc/meminfo: memFree=145032/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=105064 CPUtime=2.95
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 26425 0 0 0 286 9 0 0 20 0 1 0 116014858 107585536 24427 18446744073709551615 4194304 5895655 140734765069488 140734765064344 5081866 0 0 16781316 16929 0 0 0 17 0 0 0 12 0 0
/proc/24637/statm: 26266 24427 195 416 0 25847 0
Current children cumulated CPU time (s) 2.95
Current children cumulated vsize (KiB) 105064

[startup+6.30022 s]
/proc/loadavg: 0.98 1.15 1.03 2/60 24638
/proc/meminfo: memFree=144784/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=105064 CPUtime=6
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 26507 0 0 0 590 10 0 0 20 0 1 0 116014858 107585536 24493 18446744073709551615 4194304 5895655 140734765069488 140734765064344 4436247 0 0 16781316 16929 0 0 0 17 0 0 0 25 0 0
/proc/24637/statm: 26266 24493 195 416 0 25847 0
Current children cumulated CPU time (s) 6
Current children cumulated vsize (KiB) 105064

[startup+12.7002 s]
/proc/loadavg: 0.98 1.15 1.03 2/60 24638
/proc/meminfo: memFree=144288/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=105328 CPUtime=12.35
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 26597 0 0 0 1223 12 0 0 20 0 1 0 116014858 107855872 24571 18446744073709551615 4194304 5895655 140734765069488 140734765064344 5086823 0 0 16781316 16929 0 0 0 17 0 0 0 26 0 0
/proc/24637/statm: 26332 24571 195 416 0 25913 0
Current children cumulated CPU time (s) 12.35
Current children cumulated vsize (KiB) 105328

[startup+25.5003 s]
/proc/loadavg: 0.99 1.14 1.02 2/60 24638
/proc/meminfo: memFree=139700/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=109544 CPUtime=25
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 27977 0 0 0 2486 14 0 0 20 0 1 0 116014858 112173056 25704 18446744073709551615 4194304 5895655 140734765069488 140734765064344 4448159 0 0 16781316 16929 0 0 0 17 0 0 0 30 0 0
/proc/24637/statm: 27386 25704 195 416 0 26967 0
Current children cumulated CPU time (s) 25
Current children cumulated vsize (KiB) 109544

[startup+51.1002 s]
/proc/loadavg: 1.06 1.14 1.03 2/60 24638
/proc/meminfo: memFree=78568/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=189332 CPUtime=50.27
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 46512 0 0 0 4995 32 0 0 20 0 1 0 116014858 193875968 41604 18446744073709551615 4194304 5895655 140734765069488 140734765063448 4447033 0 0 16781316 16929 0 0 0 17 0 0 0 42 0 0
/proc/24637/statm: 47333 41604 209 416 0 46914 0
Current children cumulated CPU time (s) 50.27
Current children cumulated vsize (KiB) 189332

[startup+102.3 s]
/proc/loadavg: 1.03 1.12 1.02 2/60 24638
/proc/meminfo: memFree=83164/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=285112 CPUtime=101.04
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 136114 0 0 0 10009 95 0 0 20 0 1 0 116014858 291954688 66012 18446744073709551615 4194304 5895655 140734765069488 140734765063448 4447009 0 0 16781316 16929 0 0 0 17 0 0 0 42 0 0
/proc/24637/statm: 71278 66012 209 416 0 70859 0
Current children cumulated CPU time (s) 101.04
Current children cumulated vsize (KiB) 285112



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.8 s]
/proc/loadavg: 1.01 1.10 1.02 2/60 24638
/proc/meminfo: memFree=10048/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=713684 CPUtime=150.1
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 213707 0 0 0 14853 157 0 0 20 0 1 0 116014858 730812416 143485 18446744073709551615 4194304 5895655 140734765069488 140734765063448 4447240 0 0 16781316 16929 0 0 0 17 0 0 0 42 0 0
/proc/24637/statm: 178421 143485 209 416 0 178002 0
Current children cumulated CPU time (s) 150.1
Current children cumulated vsize (KiB) 713684

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.8 s]
/proc/loadavg: 1.01 1.10 1.02 2/60 24638
/proc/meminfo: memFree=10048/1022884 swapFree=0/0
[pid=24637] ppid=24636 vsize=713684 CPUtime=150.1
/proc/24637/stat : 24637 (cudf_fumax_bu-0) R 24636 24637 1733 0 -1 4202496 213707 0 0 0 14853 157 0 0 20 0 1 0 116014858 730812416 143485 18446744073709551615 4194304 5895655 140734765069488 140734765063448 4447240 0 0 16781316 16929 0 0 0 17 0 0 0 42 0 0
/proc/24637/statm: 178421 143485 209 416 0 178002 0
Current children cumulated CPU time (s) 150.1
Current children cumulated vsize (KiB) 713684

Child status: 0
Real time (s): 151.9
CPU time (s): 150.193
CPU user time (s): 148.589
CPU system time (s): 1.6041
CPU usage (%): 98.8765
Max. virtual memory (cumulated for all children) (KiB): 713684

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.589
system time used= 1.6041
maximum resident set size= 573940
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 213709
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 42
involuntary context switches= 17272

runsolver used 0.240015 second user time and 0.460028 second system time

The end