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/d0cc7514-c730-11df-a040-00163e3d3b7c.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/d0cc7514-c730-11df-a040-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/real/d0cc7514-c730-11df-a040-00163e3d3b7c.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

[startup+0 s]
/proc/loadavg: 0.84 0.95 0.98 2/64 5376
/proc/meminfo: memFree=103360/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=3152 CPUtime=0
/proc/5376/stat : 5376 (runsolver) R 5375 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115668108 3227648 32 18446744073709551615 134512640 134586868 4293227392 4293225440 4152079408 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5376/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.125834 s]
/proc/loadavg: 0.84 0.95 0.98 2/64 5376
/proc/meminfo: memFree=103360/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=6240 CPUtime=0.08
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 1300 0 0 0 8 0 0 0 20 0 1 0 115668108 6389760 1222 18446744073709551615 4194304 5895655 140735310804384 140735310800296 4346895 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5376/statm: 1560 1222 146 416 0 1141 0
Current children cumulated CPU time (s) 0.08
Current children cumulated vsize (KiB) 6240

[startup+0.200335 s]
/proc/loadavg: 0.84 0.95 0.98 2/64 5376
/proc/meminfo: memFree=103360/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=9516 CPUtime=0.15
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 2097 0 0 0 15 0 0 0 20 0 1 0 115668108 9744384 2019 18446744073709551615 4194304 5895655 140735310804384 140735310800296 4346988 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5376/statm: 2379 2019 146 416 0 1960 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 9516

[startup+0.300312 s]
/proc/loadavg: 0.84 0.95 0.98 2/64 5376
/proc/meminfo: memFree=103360/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=13524 CPUtime=0.25
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 3128 0 0 0 25 0 0 0 20 0 1 0 115668108 13848576 3050 18446744073709551615 4194304 5895655 140735310804384 140735310800296 4346823 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5376/statm: 3381 3050 149 416 0 2962 0
Current children cumulated CPU time (s) 0.25
Current children cumulated vsize (KiB) 13524

[startup+0.700246 s]
/proc/loadavg: 0.84 0.95 0.98 2/64 5376
/proc/meminfo: memFree=103360/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=28184 CPUtime=0.65
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 6833 0 0 0 63 2 0 0 20 0 1 0 115668108 28860416 6706 18446744073709551615 4194304 5895655 140735310804384 140735310800296 4346931 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5376/statm: 7046 6706 149 416 0 6627 0
Current children cumulated CPU time (s) 0.65
Current children cumulated vsize (KiB) 28184

[startup+1.50023 s]
/proc/loadavg: 0.84 0.95 0.98 2/65 5377
/proc/meminfo: memFree=48288/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=52576 CPUtime=1.43
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 12995 0 0 0 137 6 0 0 20 0 1 0 115668108 53837824 12819 18446744073709551615 4194304 5895655 140735310804384 140735310798984 4244871 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/5376/statm: 13144 12819 154 416 0 12725 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 52576

[startup+3.10026 s]
/proc/loadavg: 0.84 0.95 0.98 2/65 5377
/proc/meminfo: memFree=9848/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=84428 CPUtime=3.02
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 21012 0 0 0 292 10 0 0 20 0 1 0 115668108 86454272 19264 18446744073709551615 4194304 5895655 140735310804384 140735310799240 4436059 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/5376/statm: 21107 19264 203 416 0 20688 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 84428

[startup+6.30023 s]
/proc/loadavg: 0.85 0.95 0.98 2/65 5377
/proc/meminfo: memFree=9600/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=84428 CPUtime=6.17
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 21025 0 0 0 607 10 0 0 20 0 1 0 115668108 86454272 19277 18446744073709551615 4194304 5895655 140735310804384 140735310799240 4452093 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/5376/statm: 21107 19277 203 416 0 20688 0
Current children cumulated CPU time (s) 6.17
Current children cumulated vsize (KiB) 84428

[startup+12.7002 s]
/proc/loadavg: 0.87 0.95 0.98 2/65 5377
/proc/meminfo: memFree=9352/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=84428 CPUtime=12.52
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 21063 0 0 0 1240 12 0 0 20 0 1 0 115668108 86454272 19315 18446744073709551615 4194304 5895655 140735310804384 140735310799240 4454144 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/5376/statm: 21107 19315 203 416 0 20688 0
Current children cumulated CPU time (s) 12.52
Current children cumulated vsize (KiB) 84428

[startup+25.5002 s]
/proc/loadavg: 0.89 0.95 0.98 2/65 5377
/proc/meminfo: memFree=9724/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=85868 CPUtime=25.17
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 21331 0 0 0 2503 14 0 0 20 0 1 0 115668108 87928832 19583 18446744073709551615 4194304 5895655 140735310804384 140735310799240 5093840 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/5376/statm: 21467 19583 203 416 0 21048 0
Current children cumulated CPU time (s) 25.17
Current children cumulated vsize (KiB) 85868

[startup+51.1003 s]
/proc/loadavg: 0.93 0.96 0.98 2/65 5377
/proc/meminfo: memFree=9848/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=86924 CPUtime=50.59
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 21677 0 0 0 5038 21 0 0 20 0 1 0 115668108 89010176 19929 18446744073709551615 4194304 5895655 140735310804384 140735310799240 4468608 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/5376/statm: 21731 19929 203 416 0 21312 0
Current children cumulated CPU time (s) 50.59
Current children cumulated vsize (KiB) 86924

[startup+102.3 s]
/proc/loadavg: 0.97 0.96 0.98 2/65 5377
/proc/meminfo: memFree=9352/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=90400 CPUtime=101.25
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 22562 0 0 0 10096 29 0 0 20 0 1 0 115668108 92569600 20814 18446744073709551615 4194304 5895655 140735310804384 140735310799240 4446751 0 0 16781316 16929 0 0 0 17 0 0 0 24 0 0
/proc/5376/statm: 22600 20814 203 416 0 22181 0
Current children cumulated CPU time (s) 101.25
Current children cumulated vsize (KiB) 90400



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.6 s]
/proc/loadavg: 0.98 0.97 0.98 2/65 5377
/proc/meminfo: memFree=10104/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=96964 CPUtime=150.02
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202496 24200 0 0 0 14966 36 0 0 20 0 1 0 115668108 99291136 22452 18446744073709551615 4194304 5895655 140735310804384 140735310799240 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 36 0 0
/proc/5376/statm: 24241 22452 203 416 0 23822 0
Current children cumulated CPU time (s) 150.02
Current children cumulated vsize (KiB) 96964

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.709 s]
/proc/loadavg: 0.98 0.97 0.98 2/65 5377
/proc/meminfo: memFree=10104/1022884 swapFree=0/0
[pid=5376] ppid=5375 vsize=0 CPUtime=150.12
/proc/5376/stat : 5376 (cudf_fumax_bu-0) R 5375 5376 1745 0 -1 4202500 24202 0 0 0 14970 42 0 0 20 0 1 0 115668108 0 0 18446744073709551615 0 0 0 0 0 0 512 16781316 16929 18446744073709551615 0 0 17 0 0 0 36 0 0
/proc/5376/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 150.12
Current children cumulated vsize (KiB) 0

Child status: 0
Real time (s): 151.709
CPU time (s): 150.129
CPU user time (s): 149.705
CPU system time (s): 0.424026
CPU usage (%): 98.9585
Max. virtual memory (cumulated for all children) (KiB): 96964

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.705
system time used= 0.424026
maximum resident set size= 89808
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 24202
page faults= 0
swaps= 0
block input operations= 43856
block output operations= 808
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 77
involuntary context switches= 17137

runsolver used 0.236014 second user time and 0.572035 second system time

The end