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/rand220.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/install/rand220.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/embedded/install/rand220.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: 1.85 1.47 1.13 2/59 6809
/proc/meminfo: memFree=476040/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=3152 CPUtime=0
/proc/6809/stat : 6809 (runsolver) R 6808 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115997210 3227648 33 18446744073709551615 134512640 134586868 4291429456 4291427504 4151415856 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/6809/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.121295 s]
/proc/loadavg: 1.85 1.47 1.13 2/59 6809
/proc/meminfo: memFree=476040/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=4788 CPUtime=0.05
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 917 0 15 0 5 0 0 0 20 0 1 0 115997210 4902912 854 18446744073709551615 4194304 5895655 140734001740720 140734001736632 4347104 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/6809/statm: 1197 854 146 416 0 778 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 4788

[startup+0.200332 s]
/proc/loadavg: 1.85 1.47 1.13 2/59 6809
/proc/meminfo: memFree=476040/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=8116 CPUtime=0.13
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 1746 0 15 0 12 1 0 0 20 0 1 0 115997210 8310784 1683 18446744073709551615 4194304 5895655 140734001740720 140734001736632 4406643 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/6809/statm: 2029 1683 149 416 0 1610 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 8116

[startup+0.300298 s]
/proc/loadavg: 1.85 1.47 1.13 2/59 6809
/proc/meminfo: memFree=476040/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=11960 CPUtime=0.23
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 2701 0 15 0 22 1 0 0 20 0 1 0 115997210 12247040 2638 18446744073709551615 4194304 5895655 140734001740720 140734001736632 4347320 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/6809/statm: 2990 2638 149 416 0 2571 0
Current children cumulated CPU time (s) 0.23
Current children cumulated vsize (KiB) 11960

[startup+0.700218 s]
/proc/loadavg: 1.85 1.47 1.13 2/59 6809
/proc/meminfo: memFree=476040/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=26736 CPUtime=0.62
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 6451 0 15 0 60 2 0 0 20 0 1 0 115997210 27377664 6339 18446744073709551615 4194304 5895655 140734001740720 140734001736632 4383472 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/6809/statm: 6684 6339 149 416 0 6265 0
Current children cumulated CPU time (s) 0.62
Current children cumulated vsize (KiB) 26736

[startup+1.50023 s]
/proc/loadavg: 1.78 1.47 1.12 2/60 6810
/proc/meminfo: memFree=416380/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=54548 CPUtime=1.37
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 13454 0 15 0 132 5 0 0 20 0 1 0 115997210 55857152 13293 18446744073709551615 4194304 5895655 140734001740720 140734001736632 4347104 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/6809/statm: 13637 13293 149 416 0 13218 0
Current children cumulated CPU time (s) 1.37
Current children cumulated vsize (KiB) 54548

[startup+3.10023 s]
/proc/loadavg: 1.78 1.47 1.12 2/60 6810
/proc/meminfo: memFree=366408/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=104244 CPUtime=2.93
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 25799 0 16 0 283 10 0 0 20 0 1 0 115997210 106745856 23955 18446744073709551615 4194304 5895655 140734001740720 140734001735576 4452116 0 0 16781316 16929 0 0 0 17 0 0 0 14 0 0
/proc/6809/statm: 26061 23955 195 416 0 25642 0
Current children cumulated CPU time (s) 2.93
Current children cumulated vsize (KiB) 104244

[startup+6.30022 s]
/proc/loadavg: 1.72 1.46 1.12 2/60 6810
/proc/meminfo: memFree=346320/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=104636 CPUtime=6.05
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 25940 0 16 0 594 11 0 0 20 0 1 0 115997210 107147264 24092 18446744073709551615 4194304 5895655 140734001740720 140734001735576 5085209 0 0 16781316 16929 0 0 0 17 0 0 0 20 0 0
/proc/6809/statm: 26159 24092 195 416 0 25740 0
Current children cumulated CPU time (s) 6.05
Current children cumulated vsize (KiB) 104636

[startup+12.7002 s]
/proc/loadavg: 1.66 1.45 1.12 2/60 6810
/proc/meminfo: memFree=342972/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=107288 CPUtime=12.4
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 26836 0 16 0 1226 14 0 0 20 0 1 0 115997210 109862912 24958 18446744073709551615 4194304 5895655 140734001740720 140734001735576 5081866 0 0 16781316 16929 0 0 0 17 0 0 0 21 0 0
/proc/6809/statm: 26822 24958 195 416 0 26403 0
Current children cumulated CPU time (s) 12.4
Current children cumulated vsize (KiB) 107288

[startup+25.5003 s]
/proc/loadavg: 1.52 1.43 1.12 2/60 6810
/proc/meminfo: memFree=334912/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=113028 CPUtime=25.08
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 28844 0 16 0 2491 17 0 0 20 0 1 0 115997210 115740672 26919 18446744073709551615 4194304 5895655 140734001740720 140734001735576 5093926 0 0 16781316 16929 0 0 0 17 0 0 0 23 0 0
/proc/6809/statm: 28257 26919 195 416 0 27838 0
Current children cumulated CPU time (s) 25.08
Current children cumulated vsize (KiB) 113028

[startup+51.1002 s]
/proc/loadavg: 1.47 1.42 1.13 2/60 6810
/proc/meminfo: memFree=322512/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=126440 CPUtime=50.36
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 31900 0 16 0 5016 20 0 0 20 0 1 0 115997210 129474560 29961 18446744073709551615 4194304 5895655 140734001740720 140734001735576 5073290 0 0 16781316 16929 0 0 0 17 0 0 0 37 0 0
/proc/6809/statm: 31610 29961 195 416 0 31191 0
Current children cumulated CPU time (s) 50.36
Current children cumulated vsize (KiB) 126440

[startup+102.3 s]
/proc/loadavg: 1.56 1.45 1.15 2/60 7061
/proc/meminfo: memFree=86336/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=151500 CPUtime=94.77
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 589869 0 16 0 9231 246 0 0 20 0 1 0 115997210 155136000 34566 18446744073709551615 4194304 5895655 140734001740720 140734001735576 4456366 0 0 16781316 16929 0 0 0 17 0 0 0 58 0 0
/proc/6809/statm: 37875 34566 195 416 0 37456 0
Current children cumulated CPU time (s) 94.77
Current children cumulated vsize (KiB) 151500



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+158 s]
/proc/loadavg: 1.27 1.39 1.14 2/60 7061
/proc/meminfo: memFree=78524/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=158592 CPUtime=150
/proc/6809/stat : 6809 (cudf_fumax_bu-0) R 6808 6809 1750 0 -1 4202496 2141394 0 16 0 14115 885 0 0 20 0 1 0 115997210 162398208 36575 18446744073709551615 4194304 5895655 140734001740720 140734001734504 5130880 0 0 16781316 16929 0 0 0 17 0 0 0 61 0 0
/proc/6809/statm: 39648 36575 195 416 0 39229 0
Current children cumulated CPU time (s) 150
Current children cumulated vsize (KiB) 158592

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

[startup+162.3 s]
/proc/loadavg: 1.17 1.36 1.14 1/61 7062
/proc/meminfo: memFree=74672/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=158912 CPUtime=150.05
/proc/6809/stat : 6809 (cudf_fumax_bu-0) S 6808 6809 1750 0 -1 4202496 2142323 0 16 0 14120 885 0 0 20 0 1 0 115997210 162725888 37405 18446744073709551615 4194304 5895655 140734001740720 140734001733208 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 61 0 0
/proc/6809/statm: 39728 37405 195 416 0 39309 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 158912

Sending SIGKILL to process tree (bottom up)

Sending SIGKILL to -6809

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

[startup+163.1 s]
/proc/loadavg: 1.17 1.36 1.14 1/61 7062
/proc/meminfo: memFree=74672/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=158912 CPUtime=150.05
/proc/6809/stat : 6809 (cudf_fumax_bu-0) S 6808 6809 1750 0 -1 4202496 2142323 0 16 0 14120 885 0 0 20 0 1 0 115997210 162725888 37405 18446744073709551615 4194304 5895655 140734001740720 140734001733208 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 61 0 0
/proc/6809/statm: 39728 37405 195 416 0 39309 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 158912

[startup+166.3 s]
/proc/loadavg: 1.07 1.34 1.13 1/61 7062
/proc/meminfo: memFree=74672/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=158912 CPUtime=150.05
/proc/6809/stat : 6809 (cudf_fumax_bu-0) S 6808 6809 1750 0 -1 4202496 2142323 0 16 0 14120 885 0 0 20 0 1 0 115997210 162725888 37405 18446744073709551615 4194304 5895655 140734001740720 140734001733208 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 61 0 0
/proc/6809/statm: 39728 37405 195 416 0 39309 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 158912

[startup+167.1 s]
/proc/loadavg: 1.07 1.34 1.13 1/61 7062
/proc/meminfo: memFree=74672/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=158912 CPUtime=150.05
/proc/6809/stat : 6809 (cudf_fumax_bu-0) S 6808 6809 1750 0 -1 4202496 2142323 0 16 0 14120 885 0 0 20 0 1 0 115997210 162725888 37405 18446744073709551615 4194304 5895655 140734001740720 140734001733208 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 61 0 0
/proc/6809/statm: 39728 37405 195 416 0 39309 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 158912

[startup+167.5 s]
/proc/loadavg: 1.07 1.34 1.13 1/61 7062
/proc/meminfo: memFree=74548/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=158912 CPUtime=150.05
/proc/6809/stat : 6809 (cudf_fumax_bu-0) S 6808 6809 1750 0 -1 4202496 2142323 0 16 0 14120 885 0 0 20 0 1 0 115997210 162725888 37405 18446744073709551615 4194304 5895655 140734001740720 140734001733208 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 61 0 0
/proc/6809/statm: 39728 37405 195 416 0 39309 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 158912

[startup+167.9 s]
/proc/loadavg: 1.07 1.34 1.13 1/61 7062
/proc/meminfo: memFree=74548/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=158912 CPUtime=150.05
/proc/6809/stat : 6809 (cudf_fumax_bu-0) S 6808 6809 1750 0 -1 4202496 2142323 0 16 0 14120 885 0 0 20 0 1 0 115997210 162725888 37405 18446744073709551615 4194304 5895655 140734001740720 140734001733208 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 61 0 0
/proc/6809/statm: 39728 37405 195 416 0 39309 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 158912

[startup+168 s]
/proc/loadavg: 1.07 1.34 1.13 1/61 7062
/proc/meminfo: memFree=74548/1022884 swapFree=0/0
[pid=6809] ppid=6808 vsize=158912 CPUtime=150.05
/proc/6809/stat : 6809 (cudf_fumax_bu-0) S 6808 6809 1750 0 -1 4202496 2142323 0 16 0 14120 885 0 0 20 0 1 0 115997210 162725888 37405 18446744073709551615 4194304 5895655 140734001740720 140734001733208 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 61 0 0
/proc/6809/statm: 39728 37405 195 416 0 39309 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 158912

Child ended because it received signal 9 (SIGKILL)
Real time (s): 168.073
CPU time (s): 150.077
CPU user time (s): 141.209
CPU system time (s): 8.86855
CPU usage (%): 89.2928
Max. virtual memory (cumulated for all children) (KiB): 158912

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 141.209
system time used= 8.86855
maximum resident set size= 149620
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 2142323
page faults= 16
swaps= 0
block input operations= 68232
block output operations= 240
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 106
involuntary context switches= 20688

runsolver used 0.188011 second user time and 0.636039 second system time

The end