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/paranoid-size/real/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/real/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

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.17 0.99 0.99 2/60 8980
/proc/meminfo: memFree=111544/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=3152 CPUtime=0
/proc/8980/stat : 8980 (runsolver) R 8979 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 37428136 3227648 32 18446744073709551615 134512640 134586868 4290686208 4290684256 4151616560 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/8980/statm: 537 167 135 416 0 118 0

[startup+0.160421 s]
/proc/loadavg: 1.17 0.99 0.99 2/60 8980
/proc/meminfo: memFree=111544/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=11480 CPUtime=0.13
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 2597 0 0 0 11 2 0 0 20 0 1 0 37428136 11755520 2520 18446744073709551615 4194304 5895655 140733862024704 140733862020616 4410132 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/8980/statm: 2870 2520 149 416 0 2451 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 11480

[startup+0.200278 s]
/proc/loadavg: 1.17 0.99 0.99 2/60 8980
/proc/meminfo: memFree=111544/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=13988 CPUtime=0.17
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 3225 0 0 0 15 2 0 0 20 0 1 0 37428136 14323712 3148 18446744073709551615 4194304 5895655 140733862024704 140733862020616 4346931 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/8980/statm: 3497 3148 149 416 0 3078 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 13988

[startup+0.300273 s]
/proc/loadavg: 1.17 0.99 0.99 2/60 8980
/proc/meminfo: memFree=111544/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=19736 CPUtime=0.26
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 4711 0 0 0 24 2 0 0 20 0 1 0 37428136 20209664 4585 18446744073709551615 4194304 5895655 140733862024704 140733862020616 4347104 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/8980/statm: 4934 4585 149 416 0 4515 0
Current children cumulated CPU time (s) 0.26
Current children cumulated vsize (KiB) 19736

[startup+0.700203 s]
/proc/loadavg: 1.17 0.99 0.99 2/60 8980
/proc/meminfo: memFree=111544/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=41112 CPUtime=0.66
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 10065 0 0 0 60 6 0 0 20 0 1 0 37428136 42098688 9939 18446744073709551615 4194304 5895655 140733862024704 140733862020616 4348921 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/8980/statm: 10278 9939 149 416 0 9859 0
Current children cumulated CPU time (s) 0.66
Current children cumulated vsize (KiB) 41112

[startup+1.50021 s]
/proc/loadavg: 1.17 0.99 0.99 2/61 8981
/proc/meminfo: memFree=32044/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=90116 CPUtime=1.46
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 23933 0 0 0 134 12 0 0 20 0 1 0 37428136 92278784 21007 18446744073709551615 4194304 5895655 140733862024704 140733862019560 4436099 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/8980/statm: 22529 21007 203 416 0 22110 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 90116

[startup+3.10022 s]
/proc/loadavg: 1.17 0.99 0.99 2/61 8981
/proc/meminfo: memFree=9352/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=90116 CPUtime=3.05
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 23999 0 0 0 293 12 0 0 20 0 1 0 37428136 92278784 21073 18446744073709551615 4194304 5895655 140733862024704 140733862019560 4456379 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/8980/statm: 22529 21073 203 416 0 22110 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 90116

[startup+6.30023 s]
/proc/loadavg: 1.15 0.99 0.99 2/61 8981
/proc/meminfo: memFree=9104/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=90288 CPUtime=6.2
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 24020 0 0 0 606 14 0 0 20 0 1 0 37428136 92454912 21094 18446744073709551615 4194304 5895655 140733862024704 140733862019560 4446747 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/8980/statm: 22572 21094 203 416 0 22153 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 90288

[startup+12.7002 s]
/proc/loadavg: 1.14 0.99 0.99 2/61 8981
/proc/meminfo: memFree=9972/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=90824 CPUtime=12.55
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 24159 0 0 0 1240 15 0 0 20 0 1 0 37428136 93003776 21233 18446744073709551615 4194304 5895655 140733862024704 140733862019560 4452627 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/8980/statm: 22706 21233 203 416 0 22287 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 90824

[startup+25.5002 s]
/proc/loadavg: 1.11 0.99 0.99 2/61 8989
/proc/meminfo: memFree=9480/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=93028 CPUtime=25.2
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 24584 0 0 0 2502 18 0 0 20 0 1 0 37428136 95260672 21658 18446744073709551615 4194304 5895655 140733862024704 140733862019560 4452526 0 0 16781316 16929 0 0 0 17 0 0 0 12 0 0
/proc/8980/statm: 23257 21658 203 416 0 22838 0
Current children cumulated CPU time (s) 25.2
Current children cumulated vsize (KiB) 93028

[startup+51.1002 s]
/proc/loadavg: 1.07 0.99 0.99 2/61 8989
/proc/meminfo: memFree=9976/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=93312 CPUtime=50.57
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 24796 0 0 0 5035 22 0 0 20 0 1 0 37428136 95551488 21870 18446744073709551615 4194304 5895655 140733862024704 140733862019560 4456499 0 0 16781316 16929 0 0 0 17 0 0 0 22 0 0
/proc/8980/statm: 23328 21870 203 416 0 22909 0
Current children cumulated CPU time (s) 50.57
Current children cumulated vsize (KiB) 93312

[startup+102.3 s]
/proc/loadavg: 1.03 0.99 0.99 2/61 8989
/proc/meminfo: memFree=9604/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=99704 CPUtime=101.34
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 26641 0 0 0 10102 32 0 0 20 0 1 0 37428136 102096896 23715 18446744073709551615 4194304 5895655 140733862024704 140733862019560 4452880 0 0 16781316 16929 0 0 0 17 0 0 0 42 0 0
/proc/8980/statm: 24926 23715 203 416 0 24507 0
Current children cumulated CPU time (s) 101.34
Current children cumulated vsize (KiB) 99704



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.3 s]
/proc/loadavg: 1.01 0.99 0.99 2/61 8989
/proc/meminfo: memFree=9604/1022884 swapFree=0/0
[pid=8980] ppid=8979 vsize=113284 CPUtime=150.01
/proc/8980/stat : 8980 (cudf_fumax_bu-0) R 8979 8980 32685 0 -1 4202496 180585 0 0 0 14912 89 0 0 20 0 1 0 37428136 116002816 26810 18446744073709551615 4194304 5895655 140733862024704 140733862019560 5073382 0 0 16781316 16929 0 0 0 17 0 0 0 50 0 0
/proc/8980/statm: 28321 26810 203 416 0 27902 0
Current children cumulated CPU time (s) 150.01
Current children cumulated vsize (KiB) 113284

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.387
CPU time (s): 150.097
CPU user time (s): 149.165
CPU system time (s): 0.932058
CPU usage (%): 99.1484
Max. virtual memory (cumulated for all children) (KiB): 113284

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.165
system time used= 0.932058
maximum resident set size= 107240
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 180587
page faults= 0
swaps= 0
block input operations= 43424
block output operations= 824
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 71
involuntary context switches= 2334

runsolver used 0.240015 second user time and 0.48403 second system time

The end