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/rand209.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/install/rand209.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/embedded/install/rand209.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.63 1.34 1.08 2/56 11075
/proc/meminfo: memFree=457024/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=3152 CPUtime=0
/proc/11075/stat : 11075 (runsolver) D 11074 11075 32685 0 -1 4202560 75 0 0 0 0 0 0 0 20 0 1 0 37770799 3227648 96 18446744073709551615 134512640 134586868 4294869696 4294867744 4152112176 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/11075/statm: 788 96 64 19 0 73 0

[startup+0.197583 s]
/proc/loadavg: 1.63 1.34 1.08 2/56 11075
/proc/meminfo: memFree=457024/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=7720 CPUtime=0.13
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 1661 0 15 0 12 1 0 0 20 0 1 0 37770799 7905280 1598 18446744073709551615 4194304 5895655 140735580624864 140735580620776 5071104 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/11075/statm: 1930 1598 149 416 0 1511 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 7720

[startup+0.200323 s]
/proc/loadavg: 1.63 1.34 1.08 2/56 11075
/proc/meminfo: memFree=457024/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=7852 CPUtime=0.13
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 1685 0 15 0 12 1 0 0 20 0 1 0 37770799 8040448 1622 18446744073709551615 4194304 5895655 140735580624864 140735580620776 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/11075/statm: 1963 1622 149 416 0 1544 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 7852

[startup+0.300346 s]
/proc/loadavg: 1.63 1.34 1.08 2/56 11075
/proc/meminfo: memFree=457024/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=11564 CPUtime=0.22
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 2604 0 15 0 20 2 0 0 20 0 1 0 37770799 11841536 2541 18446744073709551615 4194304 5895655 140735580624864 140735580620776 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/11075/statm: 2891 2541 149 416 0 2472 0
Current children cumulated CPU time (s) 0.22
Current children cumulated vsize (KiB) 11564

[startup+0.700227 s]
/proc/loadavg: 1.63 1.34 1.08 2/56 11075
/proc/meminfo: memFree=457024/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=24888 CPUtime=0.63
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 5989 0 15 0 58 5 0 0 20 0 1 0 37770799 25485312 5877 18446744073709551615 4194304 5895655 140735580624864 140735580620776 4347111 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/11075/statm: 6222 5877 149 416 0 5803 0
Current children cumulated CPU time (s) 0.63
Current children cumulated vsize (KiB) 24888

[startup+1.50035 s]
/proc/loadavg: 1.63 1.34 1.08 2/57 11076
/proc/meminfo: memFree=405176/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=51512 CPUtime=1.4
/proc/11075/stat : 11075 (cudf_fumax_bu-0) D 11074 11075 32685 0 -1 4202496 12678 0 15 0 133 7 0 0 20 0 1 0 37770799 52748288 12517 18446744073709551615 4194304 5895655 140735580624864 140735580620776 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 8 0 0
/proc/11075/statm: 12878 12517 149 416 0 12459 0
Current children cumulated CPU time (s) 1.4
Current children cumulated vsize (KiB) 51512

[startup+3.10024 s]
/proc/loadavg: 1.63 1.34 1.08 2/57 11076
/proc/meminfo: memFree=357808/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=105076 CPUtime=2.92
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 26333 0 16 0 279 13 0 0 20 0 1 0 37770799 107597824 24366 18446744073709551615 4194304 5895655 140735580624864 140735580619720 4436054 0 0 16781316 16929 0 0 0 17 0 0 0 15 0 0
/proc/11075/statm: 26269 24366 195 416 0 25850 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 105076

[startup+6.30025 s]
/proc/loadavg: 1.58 1.34 1.08 2/57 11076
/proc/meminfo: memFree=323832/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=105076 CPUtime=6.09
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 26494 0 16 0 596 13 0 0 20 0 1 0 37770799 107597824 24512 18446744073709551615 4194304 5895655 140735580624864 140735580619720 5085787 0 0 16781316 16929 0 0 0 17 0 0 0 16 0 0
/proc/11075/statm: 26269 24512 195 416 0 25850 0
Current children cumulated CPU time (s) 6.09
Current children cumulated vsize (KiB) 105076

[startup+12.7002 s]
/proc/loadavg: 1.53 1.33 1.07 2/57 11076
/proc/meminfo: memFree=323336/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=105688 CPUtime=12.45
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 26656 0 16 0 1231 14 0 0 20 0 1 0 37770799 108224512 24651 18446744073709551615 4194304 5895655 140735580624864 140735580619720 5084964 0 0 16781316 16929 0 0 0 17 0 0 0 17 0 0
/proc/11075/statm: 26422 24651 195 416 0 26003 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 105688

[startup+25.5003 s]
/proc/loadavg: 1.41 1.32 1.07 2/57 11076
/proc/meminfo: memFree=318252/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=110192 CPUtime=25.16
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 28076 0 16 0 2500 16 0 0 20 0 1 0 37770799 112836608 25867 18446744073709551615 4194304 5895655 140735580624864 140735580619720 4451200 0 0 16781316 16929 0 0 0 17 0 0 0 20 0 0
/proc/11075/statm: 27548 25867 195 416 0 27129 0
Current children cumulated CPU time (s) 25.16
Current children cumulated vsize (KiB) 110192

[startup+51.1003 s]
/proc/loadavg: 1.27 1.29 1.07 2/57 11076
/proc/meminfo: memFree=307712/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=121984 CPUtime=50.58
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 30771 0 16 0 5039 19 0 0 20 0 1 0 37770799 124911616 28476 18446744073709551615 4194304 5895655 140735580624864 140735580619720 5090082 0 0 16781316 16929 0 0 0 17 0 0 0 25 0 0
/proc/11075/statm: 30496 28476 195 416 0 30077 0
Current children cumulated CPU time (s) 50.58
Current children cumulated vsize (KiB) 121984

[startup+102.3 s]
/proc/loadavg: 1.20 1.26 1.07 2/57 11076
/proc/meminfo: memFree=286880/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=141128 CPUtime=101.27
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 750873 0 16 0 9797 330 0 0 20 0 1 0 37770799 144515072 33633 18446744073709551615 4194304 5895655 140735580624864 140735580618616 5082252 0 0 16781316 16929 0 0 0 17 0 0 0 50 0 0
/proc/11075/statm: 35282 33633 195 416 0 34863 0
Current children cumulated CPU time (s) 101.27
Current children cumulated vsize (KiB) 141128



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.6 s]
/proc/loadavg: 1.08 1.22 1.07 2/57 11076
/proc/meminfo: memFree=282912/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=152228 CPUtime=150.09
/proc/11075/stat : 11075 (cudf_fumax_bu-0) R 11074 11075 32685 0 -1 4202496 2461661 0 17 0 14055 954 0 0 20 0 1 0 37770799 155881472 34979 18446744073709551615 4194304 5895655 140735580624864 140735580618648 5131085 0 0 16781316 16929 0 0 0 17 0 0 0 77 0 0
/proc/11075/statm: 38057 34979 208 416 0 37638 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 152228

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

Sending SIGKILL to process tree (bottom up)

Sending SIGKILL to -11075

Solver just ended. Dumping a history of the last processes samples

[startup+153.5 s]
/proc/loadavg: 1.08 1.22 1.07 1/59 11082
/proc/meminfo: memFree=266032/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=173224 CPUtime=150.13
/proc/11075/stat : 11075 (cudf_fumax_bu-0) S 11074 11075 32685 0 -1 4202496 2465150 0 17 0 14058 955 0 0 20 0 1 0 37770799 177381376 38225 18446744073709551615 4194304 5895655 140735580624864 140735580617240 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 77 0 0
/proc/11075/statm: 43306 38225 208 416 0 42887 0
Current children cumulated CPU time (s) 150.13
Current children cumulated vsize (KiB) 173224

[startup+156.7 s]
/proc/loadavg: 1.00 1.20 1.06 1/60 11092
/proc/meminfo: memFree=243572/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=173224 CPUtime=150.13
/proc/11075/stat : 11075 (cudf_fumax_bu-0) S 11074 11075 32685 0 -1 4202496 2465150 0 17 0 14058 955 0 0 20 0 1 0 37770799 177381376 38225 18446744073709551615 4194304 5895655 140735580624864 140735580617240 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 77 0 0
/proc/11075/statm: 43306 38225 208 416 0 42887 0
Current children cumulated CPU time (s) 150.13
Current children cumulated vsize (KiB) 173224

[startup+159.9 s]
/proc/loadavg: 1.00 1.19 1.06 2/63 11188
/proc/meminfo: memFree=200900/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=173224 CPUtime=150.13
/proc/11075/stat : 11075 (cudf_fumax_bu-0) S 11074 11075 32685 0 -1 4202496 2465150 0 17 0 14058 955 0 0 20 0 1 0 37770799 177381376 38225 18446744073709551615 4194304 5895655 140735580624864 140735580617240 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 77 0 0
/proc/11075/statm: 43306 38225 208 416 0 42887 0
Current children cumulated CPU time (s) 150.13
Current children cumulated vsize (KiB) 173224

[startup+160.703 s]
/proc/loadavg: 1.00 1.19 1.06 2/60 11189
/proc/meminfo: memFree=194352/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=173224 CPUtime=150.13
/proc/11075/stat : 11075 (cudf_fumax_bu-0) S 11074 11075 32685 0 -1 4202496 2465150 0 17 0 14058 955 0 0 20 0 1 0 37770799 177381376 38225 18446744073709551615 4194304 5895655 140735580624864 140735580617240 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 77 0 0
/proc/11075/statm: 43306 38225 208 416 0 42887 0
Current children cumulated CPU time (s) 150.13
Current children cumulated vsize (KiB) 173224

[startup+161.1 s]
/proc/loadavg: 1.00 1.19 1.06 2/60 11189
/proc/meminfo: memFree=194352/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=173224 CPUtime=150.13
/proc/11075/stat : 11075 (cudf_fumax_bu-0) S 11074 11075 32685 0 -1 4202496 2465150 0 17 0 14058 955 0 0 20 0 1 0 37770799 177381376 38225 18446744073709551615 4194304 5895655 140735580624864 140735580617240 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 77 0 0
/proc/11075/statm: 43306 38225 208 416 0 42887 0
Current children cumulated CPU time (s) 150.13
Current children cumulated vsize (KiB) 173224

[startup+161.5 s]
/proc/loadavg: 1.00 1.19 1.06 2/60 11189
/proc/meminfo: memFree=194352/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=173224 CPUtime=150.13
/proc/11075/stat : 11075 (cudf_fumax_bu-0) S 11074 11075 32685 0 -1 4202496 2465150 0 17 0 14058 955 0 0 20 0 1 0 37770799 177381376 38225 18446744073709551615 4194304 5895655 140735580624864 140735580617240 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 77 0 0
/proc/11075/statm: 43306 38225 208 416 0 42887 0
Current children cumulated CPU time (s) 150.13
Current children cumulated vsize (KiB) 173224

[startup+161.6 s]
/proc/loadavg: 1.00 1.19 1.06 2/60 11189
/proc/meminfo: memFree=194352/1022884 swapFree=0/0
[pid=11075] ppid=11074 vsize=173224 CPUtime=150.13
/proc/11075/stat : 11075 (cudf_fumax_bu-0) S 11074 11075 32685 0 -1 4202496 2465150 0 17 0 14058 955 0 0 20 0 1 0 37770799 177381376 38225 18446744073709551615 4194304 5895655 140735580624864 140735580617240 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 77 0 0
/proc/11075/statm: 43306 38225 208 416 0 42887 0
Current children cumulated CPU time (s) 150.13
Current children cumulated vsize (KiB) 173224

Child ended because it received signal 9 (SIGKILL)
Real time (s): 161.665
CPU time (s): 150.157
CPU user time (s): 140.589
CPU system time (s): 9.5686
CPU usage (%): 92.8821
Max. virtual memory (cumulated for all children) (KiB): 173224

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 140.589
system time used= 9.5686
maximum resident set size= 158108
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 2465150
page faults= 17
swaps= 0
block input operations= 71680
block output operations= 248
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 106
involuntary context switches= 2298

runsolver used 0.228014 second user time and 0.548034 second system time

The end