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/rand937.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/install/rand937.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/embedded/install/rand937.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.87 1.11 1.05 2/56 11335
/proc/meminfo: memFree=190388/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=3152 CPUtime=0
/proc/11335/stat : 11335 (runsolver) R 11334 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 37803518 3227648 32 18446744073709551615 134512640 134586868 4289509856 4289507904 4152116272 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/11335/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.183356 s]
/proc/loadavg: 0.87 1.11 1.05 2/56 11335
/proc/meminfo: memFree=190388/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=12620 CPUtime=0.17
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 2880 0 0 0 16 1 0 0 20 0 1 0 37803518 12922880 2803 18446744073709551615 4194304 5895655 140736373047280 140736373043192 5087514 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/11335/statm: 3155 2803 149 416 0 2736 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 12620

[startup+0.20028 s]
/proc/loadavg: 0.87 1.11 1.05 2/56 11335
/proc/meminfo: memFree=190388/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=13544 CPUtime=0.19
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 3109 0 0 0 18 1 0 0 20 0 1 0 37803518 13869056 3032 18446744073709551615 4194304 5895655 140736373047280 140736373043192 5130336 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/11335/statm: 3386 3032 149 416 0 2967 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 13544

[startup+0.300264 s]
/proc/loadavg: 0.87 1.11 1.05 2/56 11335
/proc/meminfo: memFree=190388/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=18816 CPUtime=0.29
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 4497 0 0 0 28 1 0 0 20 0 1 0 37803518 19267584 4371 18446744073709551615 4194304 5895655 140736373047280 140736373043192 4300721 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/11335/statm: 4704 4371 149 416 0 4285 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 18816

[startup+0.700229 s]
/proc/loadavg: 0.87 1.11 1.05 2/56 11335
/proc/meminfo: memFree=190388/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=38444 CPUtime=0.69
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 9434 0 0 0 67 2 0 0 20 0 1 0 37803518 39366656 9259 18446744073709551615 4194304 5895655 140736373047280 140736373043192 5107386 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/11335/statm: 9611 9259 149 416 0 9192 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 38444

[startup+1.50021 s]
/proc/loadavg: 0.87 1.11 1.05 2/57 11336
/proc/meminfo: memFree=136928/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=71696 CPUtime=1.48
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 17834 0 0 0 142 6 0 0 20 0 1 0 37803518 73416704 17562 18446744073709551615 4194304 5895655 140736373047280 140736373043192 4346904 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/11335/statm: 17924 17562 149 416 0 17505 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 71696

[startup+3.10023 s]
/proc/loadavg: 0.88 1.11 1.05 2/57 11336
/proc/meminfo: memFree=93652/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=104964 CPUtime=3.08
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 26398 0 0 0 300 8 0 0 20 0 1 0 37803518 107483136 24404 18446744073709551615 4194304 5895655 140736373047280 140736373042136 4456401 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/11335/statm: 26241 24404 195 416 0 25822 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 104964

[startup+6.30023 s]
/proc/loadavg: 0.88 1.11 1.05 2/57 11336
/proc/meminfo: memFree=93032/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=105096 CPUtime=6.24
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 26502 0 0 0 616 8 0 0 20 0 1 0 37803518 107618304 24498 18446744073709551615 4194304 5895655 140736373047280 140736373042136 4447943 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/11335/statm: 26274 24498 195 416 0 25855 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 105096

[startup+12.7003 s]
/proc/loadavg: 0.90 1.11 1.05 2/57 11336
/proc/meminfo: memFree=90552/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=107016 CPUtime=12.61
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 27228 0 0 0 1252 9 0 0 20 0 1 0 37803518 109584384 25082 18446744073709551615 4194304 5895655 140736373047280 140736373042136 4446747 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/11335/statm: 26754 25082 195 416 0 26335 0
Current children cumulated CPU time (s) 12.61
Current children cumulated vsize (KiB) 107016

[startup+25.5002 s]
/proc/loadavg: 0.91 1.10 1.05 2/57 11336
/proc/meminfo: memFree=83484/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=112612 CPUtime=25.27
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 29096 0 0 0 2515 12 0 0 20 0 1 0 37803518 115314688 26877 18446744073709551615 4194304 5895655 140736373047280 140736373042136 5084783 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/11335/statm: 28153 26877 195 416 0 27734 0
Current children cumulated CPU time (s) 25.27
Current children cumulated vsize (KiB) 112612

[startup+51.1002 s]
/proc/loadavg: 0.94 1.09 1.05 2/57 11336
/proc/meminfo: memFree=9608/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=223652 CPUtime=50.67
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 59557 0 0 0 5038 29 0 0 20 0 1 0 37803518 229019648 52390 18446744073709551615 4194304 5895655 140736373047280 140736373041000 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 13 0 0
/proc/11335/statm: 55913 52390 207 416 0 55494 0
Current children cumulated CPU time (s) 50.67
Current children cumulated vsize (KiB) 223652

[startup+102.3 s]
/proc/loadavg: 0.97 1.07 1.04 2/57 11336
/proc/meminfo: memFree=134088/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=174332 CPUtime=101.6
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 80695 0 0 0 10094 66 0 0 20 0 1 0 37803518 178515968 42195 18446744073709551615 4194304 5895655 140736373047280 140736373042136 4447203 0 0 16781316 16929 0 0 0 17 0 0 0 13 0 0
/proc/11335/statm: 43583 42195 207 416 0 43164 0
Current children cumulated CPU time (s) 101.6
Current children cumulated vsize (KiB) 174332



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151 s]
/proc/loadavg: 1.04 1.08 1.05 2/57 11336
/proc/meminfo: memFree=9760/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=387444 CPUtime=150.05
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 117302 0 0 0 14901 104 0 0 20 0 1 0 37803518 396742656 78700 18446744073709551615 4194304 5895655 140736373047280 140736373041240 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 13 0 0
/proc/11335/statm: 96861 78700 207 416 0 96442 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 387444

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 s]
/proc/loadavg: 1.04 1.08 1.05 2/57 11336
/proc/meminfo: memFree=9760/1022884 swapFree=0/0
[pid=11335] ppid=11334 vsize=387444 CPUtime=150.05
/proc/11335/stat : 11335 (cudf_fumax_bu-0) R 11334 11335 32685 0 -1 4202496 117302 0 0 0 14901 104 0 0 20 0 1 0 37803518 396742656 78700 18446744073709551615 4194304 5895655 140736373047280 140736373041240 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 13 0 0
/proc/11335/statm: 96861 78700 207 416 0 96442 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 387444

Child status: 0
Real time (s): 151.06
CPU time (s): 150.121
CPU user time (s): 149.045
CPU system time (s): 1.07607
CPU usage (%): 99.3789
Max. virtual memory (cumulated for all children) (KiB): 387444

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.045
system time used= 1.07607
maximum resident set size= 314800
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 117304
page faults= 0
swaps= 0
block input operations= 0
block output operations= 128
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 15
involuntary context switches= 2300

runsolver used 0.236014 second user time and 0.444027 second system time

The end