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/real/56e31304-c17a-11df-b070-00163e3d3b7c.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/56e31304-c17a-11df-b070-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/embedded/real/56e31304-c17a-11df-b070-00163e3d3b7c.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: 0.97 0.95 0.97 2/64 7176
/proc/meminfo: memFree=233300/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=2148 CPUtime=0
/proc/7176/stat : 7176 (cudf_fumax_bu-0) D 7175 7176 1745 0 -1 4202496 245 0 0 0 0 0 0 0 20 0 1 0 116122658 2199552 168 18446744073709551615 4194304 5895655 140735556474960 140735556470872 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/7176/statm: 537 168 135 416 0 118 0

[startup+0.156221 s]
/proc/loadavg: 0.97 0.95 0.97 2/64 7176
/proc/meminfo: memFree=233300/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=8480 CPUtime=0.12
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 1862 0 0 0 12 0 0 0 20 0 1 0 116122658 8683520 1785 18446744073709551615 4194304 5895655 140735556474960 140735556470872 4347104 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/7176/statm: 2120 1785 149 416 0 1701 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 8480

[startup+0.200321 s]
/proc/loadavg: 0.97 0.95 0.97 2/64 7176
/proc/meminfo: memFree=233300/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=10260 CPUtime=0.16
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 2280 0 0 0 15 1 0 0 20 0 1 0 116122658 10506240 2203 18446744073709551615 4194304 5895655 140735556474960 140735556470680 4406748 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/7176/statm: 2565 2203 149 416 0 2146 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 10260

[startup+0.300305 s]
/proc/loadavg: 0.97 0.95 0.97 2/64 7176
/proc/meminfo: memFree=233300/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=14880 CPUtime=0.25
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 3435 0 0 0 23 2 0 0 20 0 1 0 116122658 15237120 3358 18446744073709551615 4194304 5895655 140735556474960 140735556470808 4408561 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/7176/statm: 3720 3358 149 416 0 3301 0
Current children cumulated CPU time (s) 0.25
Current children cumulated vsize (KiB) 14880

[startup+0.700222 s]
/proc/loadavg: 0.97 0.95 0.97 2/64 7176
/proc/meminfo: memFree=233300/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=27564 CPUtime=0.62
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 6679 0 0 0 58 4 0 0 20 0 1 0 116122658 28225536 6553 18446744073709551615 4194304 5895655 140735556474960 140735556470872 4346895 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/7176/statm: 6891 6553 149 416 0 6472 0
Current children cumulated CPU time (s) 0.62
Current children cumulated vsize (KiB) 27564

[startup+1.50023 s]
/proc/loadavg: 0.97 0.95 0.97 2/65 7177
/proc/meminfo: memFree=180296/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=50608 CPUtime=1.41
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 12485 0 0 0 133 8 0 0 20 0 1 0 116122658 51822592 12310 18446744073709551615 4194304 5895655 140735556474960 140735556469768 4244291 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/7176/statm: 12652 12310 154 416 0 12233 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 50608

[startup+3.10022 s]
/proc/loadavg: 0.98 0.95 0.97 2/65 7177
/proc/meminfo: memFree=149776/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=70580 CPUtime=3
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 16938 0 0 0 289 11 0 0 20 0 1 0 116122658 72273920 15890 18446744073709551615 4194304 5895655 140735556474960 140735556469816 5073438 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/7176/statm: 17645 15890 195 416 0 17226 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 70580

[startup+6.30023 s]
/proc/loadavg: 0.98 0.95 0.97 2/65 7177
/proc/meminfo: memFree=148288/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=72004 CPUtime=6.17
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 17378 0 0 0 604 13 0 0 20 0 1 0 116122658 73732096 16320 18446744073709551615 4194304 5895655 140735556474960 140735556469816 4452854 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/7176/statm: 18001 16320 195 416 0 17582 0
Current children cumulated CPU time (s) 6.17
Current children cumulated vsize (KiB) 72004

[startup+12.7002 s]
/proc/loadavg: 0.98 0.95 0.97 2/65 7177
/proc/meminfo: memFree=136880/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=87540 CPUtime=12.5
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 23315 0 0 0 1234 16 0 0 20 0 1 0 116122658 89640960 20422 18446744073709551615 4194304 5895655 140735556474960 140735556468632 4446984 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/7176/statm: 21885 20422 209 416 0 21466 0
Current children cumulated CPU time (s) 12.5
Current children cumulated vsize (KiB) 87540

[startup+25.5003 s]
/proc/loadavg: 0.98 0.95 0.97 2/65 7177
/proc/meminfo: memFree=116420/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=99872 CPUtime=25.2
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 33965 0 0 0 2496 24 0 0 20 0 1 0 116122658 102268928 23994 18446744073709551615 4194304 5895655 140735556474960 140735556469816 4447069 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/7176/statm: 24968 23994 209 416 0 24549 0
Current children cumulated CPU time (s) 25.2
Current children cumulated vsize (KiB) 99872

[startup+51.1002 s]
/proc/loadavg: 0.99 0.95 0.97 2/65 7177
/proc/meminfo: memFree=43012/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=209552 CPUtime=50.63
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 52585 0 0 0 5025 38 0 0 20 0 1 0 116122658 214581248 42564 18446744073709551615 4194304 5895655 140735556474960 140735556468920 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/7176/statm: 52388 42564 209 416 0 51969 0
Current children cumulated CPU time (s) 50.63
Current children cumulated vsize (KiB) 209552

[startup+102.3 s]
/proc/loadavg: 0.99 0.96 0.97 2/65 7177
/proc/meminfo: memFree=96332/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=161612 CPUtime=101.45
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 73803 0 0 0 10081 64 0 0 20 0 1 0 116122658 165490688 34724 18446744073709551615 4194304 5895655 140735556474960 140735556468632 4447521 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/7176/statm: 40403 34724 209 416 0 39984 0
Current children cumulated CPU time (s) 101.45
Current children cumulated vsize (KiB) 161612



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.2 s]
/proc/loadavg: 0.99 0.96 0.97 2/65 7177
/proc/meminfo: memFree=9532/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=291840 CPUtime=150.02
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 95544 0 0 0 14912 90 0 0 20 0 1 0 116122658 298844160 56341 18446744073709551615 4194304 5895655 140735556474960 140735556468920 4447285 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/7176/statm: 72960 56341 209 416 0 72541 0
Current children cumulated CPU time (s) 150.02
Current children cumulated vsize (KiB) 291840

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.2 s]
/proc/loadavg: 0.99 0.96 0.97 2/65 7177
/proc/meminfo: memFree=9532/1022884 swapFree=0/0
[pid=7176] ppid=7175 vsize=291840 CPUtime=150.02
/proc/7176/stat : 7176 (cudf_fumax_bu-0) R 7175 7176 1745 0 -1 4202496 95544 0 0 0 14912 90 0 0 20 0 1 0 116122658 298844160 56341 18446744073709551615 4194304 5895655 140735556474960 140735556468920 4447285 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/7176/statm: 72960 56341 209 416 0 72541 0
Current children cumulated CPU time (s) 150.02
Current children cumulated vsize (KiB) 291840

Child status: 0
Real time (s): 151.249
CPU time (s): 150.073
CPU user time (s): 149.153
CPU system time (s): 0.920057
CPU usage (%): 99.2225
Max. virtual memory (cumulated for all children) (KiB): 291840

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.153
system time used= 0.920057
maximum resident set size= 225364
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 95546
page faults= 0
swaps= 0
block input operations= 41984
block output operations= 72
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 22
involuntary context switches= 17103

runsolver used 0.228014 second user time and 0.468029 second system time

The end