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/rand717.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/install/rand717.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/embedded/install/rand717.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.85 1.06 1.01 2/59 24643
/proc/meminfo: memFree=583432/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=3152 CPUtime=0
/proc/24643/stat : 24643 (runsolver) R 24642 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 116031069 3227648 33 18446744073709551615 134512640 134586868 4294576256 4294574304 4151653424 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/24643/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.184081 s]
/proc/loadavg: 0.85 1.06 1.01 2/59 24643
/proc/meminfo: memFree=583432/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=13544 CPUtime=0.16
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 3112 0 0 0 14 2 0 0 20 0 1 0 116031069 13869056 3034 18446744073709551615 4194304 5895655 140735207478976 140735207474888 4983654 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/24643/statm: 3386 3034 149 416 0 2967 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 13544

[startup+0.200247 s]
/proc/loadavg: 0.85 1.06 1.01 2/59 24643
/proc/meminfo: memFree=583432/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=14468 CPUtime=0.18
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 3342 0 0 0 16 2 0 0 20 0 1 0 116031069 14815232 3264 18446744073709551615 4194304 5895655 140735207478976 140735207474888 4347066 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/24643/statm: 3617 3264 149 416 0 3198 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 14468

[startup+0.300179 s]
/proc/loadavg: 0.85 1.06 1.01 2/59 24643
/proc/meminfo: memFree=583432/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=20268 CPUtime=0.27
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 4833 0 0 0 25 2 0 0 20 0 1 0 116031069 20754432 4706 18446744073709551615 4194304 5895655 140735207478976 140735207474888 4347082 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/24643/statm: 5067 4706 149 416 0 4648 0
Current children cumulated CPU time (s) 0.27
Current children cumulated vsize (KiB) 20268

[startup+0.700175 s]
/proc/loadavg: 0.85 1.06 1.01 2/59 24643
/proc/meminfo: memFree=583432/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=40556 CPUtime=0.68
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 9976 0 0 0 64 4 0 0 20 0 1 0 116031069 41529344 9800 18446744073709551615 4194304 5895655 140735207478976 140735207474888 4347320 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/24643/statm: 10139 9800 149 416 0 9720 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 40556

[startup+1.50018 s]
/proc/loadavg: 0.85 1.06 1.01 2/60 24644
/proc/meminfo: memFree=500212/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=77916 CPUtime=1.46
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 19034 0 0 0 140 6 0 0 20 0 1 0 116031069 79785984 18761 18446744073709551615 4194304 5895655 140735207478976 140735207474296 4360054 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/24643/statm: 19479 18761 164 416 0 19060 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 77916

[startup+3.1002 s]
/proc/loadavg: 0.87 1.06 1.01 2/60 24644
/proc/meminfo: memFree=449620/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=106364 CPUtime=3.06
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 30353 0 0 0 298 8 0 0 20 0 1 0 116031069 108916736 25033 18446744073709551615 4194304 5895655 140735207478976 140735207473832 4474764 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/24643/statm: 26591 25033 195 416 0 26172 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 106364

[startup+6.30022 s]
/proc/loadavg: 0.87 1.06 1.01 2/60 24644
/proc/meminfo: memFree=449372/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=106500 CPUtime=6.23
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 30420 0 0 0 615 8 0 0 20 0 1 0 116031069 109056000 25091 18446744073709551615 4194304 5895655 140735207478976 140735207473832 4452854 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/24643/statm: 26625 25091 195 416 0 26206 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 106500

[startup+12.7002 s]
/proc/loadavg: 0.89 1.06 1.00 2/60 24644
/proc/meminfo: memFree=448876/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=108620 CPUtime=12.56
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 30860 0 0 0 1247 9 0 0 20 0 1 0 116031069 111226880 25466 18446744073709551615 4194304 5895655 140735207478976 140735207473832 4452032 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/24643/statm: 27155 25466 195 416 0 26736 0
Current children cumulated CPU time (s) 12.56
Current children cumulated vsize (KiB) 108620

[startup+25.5002 s]
/proc/loadavg: 0.90 1.06 1.00 2/60 24644
/proc/meminfo: memFree=445032/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=111020 CPUtime=25.26
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 31871 0 0 0 2516 10 0 0 20 0 1 0 116031069 113684480 26281 18446744073709551615 4194304 5895655 140735207478976 140735207473832 5082110 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/24643/statm: 27755 26281 195 416 0 27336 0
Current children cumulated CPU time (s) 25.26
Current children cumulated vsize (KiB) 111020

[startup+51.1002 s]
/proc/loadavg: 0.93 1.05 1.00 2/60 24644
/proc/meminfo: memFree=432880/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=123948 CPUtime=50.65
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 51793 0 0 0 5045 20 0 0 20 0 1 0 116031069 126922752 29088 18446744073709551615 4194304 5895655 140735207478976 140735207473832 5085159 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/24643/statm: 30987 29088 195 416 0 30568 0
Current children cumulated CPU time (s) 50.65
Current children cumulated vsize (KiB) 123948

[startup+102.3 s]
/proc/loadavg: 0.97 1.04 1.00 2/60 24644
/proc/meminfo: memFree=412296/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=144596 CPUtime=101.36
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 276675 0 0 0 10007 129 0 0 20 0 1 0 116031069 148066304 34220 18446744073709551615 4194304 5895655 140735207478976 140735207472728 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 14 0 0
/proc/24643/statm: 36149 34220 195 416 0 35730 0
Current children cumulated CPU time (s) 101.36
Current children cumulated vsize (KiB) 144596



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.5 s]
/proc/loadavg: 0.98 1.03 1.00 2/60 24644
/proc/meminfo: memFree=401880/1022884 swapFree=0/0
[pid=24643] ppid=24642 vsize=158956 CPUtime=150
/proc/24643/stat : 24643 (cudf_fumax_bu-0) R 24642 24643 1733 0 -1 4202496 829501 0 0 0 14629 371 0 0 20 0 1 0 116031069 162770944 36779 18446744073709551615 4194304 5895655 140735207478976 140735207473832 4452535 0 0 16781316 16929 0 0 0 17 0 0 0 32 0 0
/proc/24643/statm: 39739 36779 195 416 0 39320 0
Current children cumulated CPU time (s) 150
Current children cumulated vsize (KiB) 158956

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.57
CPU time (s): 150.069
CPU user time (s): 146.349
CPU system time (s): 3.72023
CPU usage (%): 99.0099
Max. virtual memory (cumulated for all children) (KiB): 158956

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 146.349
system time used= 3.72023
maximum resident set size= 147116
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 829503
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 248
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 76
involuntary context switches= 17140

runsolver used 0.252015 second user time and 0.536033 second system time

The end