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/4e539b28-d46c-11df-8f4f-00163e3d3b7c.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/4e539b28-d46c-11df-8f4f-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/embedded/real/4e539b28-d46c-11df-8f4f-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

[startup+0 s]
/proc/loadavg: 0.89 0.94 0.96 2/60 11459
/proc/meminfo: memFree=274324/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=3152 CPUtime=0
/proc/11459/stat : 11459 (runsolver) R 11458 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 37929269 3227648 32 18446744073709551615 134512640 134586868 4291962144 4291960192 4151764016 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/11459/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.144473 s]
/proc/loadavg: 0.89 0.94 0.96 2/60 11459
/proc/meminfo: memFree=274324/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=7440 CPUtime=0.12
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 1590 0 0 0 12 0 0 0 20 0 1 0 37929269 7618560 1512 18446744073709551615 4194304 5895655 140733550291040 140733550286952 5130186 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/11459/statm: 1860 1512 149 416 0 1441 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 7440

[startup+0.200324 s]
/proc/loadavg: 0.89 0.94 0.96 2/60 11459
/proc/meminfo: memFree=274324/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=9616 CPUtime=0.17
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 2141 0 0 0 17 0 0 0 20 0 1 0 37929269 9846784 2063 18446744073709551615 4194304 5895655 140733550291040 140733550286952 4410157 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/11459/statm: 2404 2063 149 416 0 1985 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 9616

[startup+0.300307 s]
/proc/loadavg: 0.89 0.94 0.96 2/60 11459
/proc/meminfo: memFree=274324/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=13456 CPUtime=0.27
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 3098 0 0 0 27 0 0 0 20 0 1 0 37929269 13778944 3020 18446744073709551615 4194304 5895655 140733550291040 140733550286952 4300725 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/11459/statm: 3364 3020 149 416 0 2945 0
Current children cumulated CPU time (s) 0.27
Current children cumulated vsize (KiB) 13456

[startup+0.700233 s]
/proc/loadavg: 0.89 0.94 0.96 2/60 11459
/proc/meminfo: memFree=274324/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=27308 CPUtime=0.66
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 6591 0 0 0 64 2 0 0 20 0 1 0 37929269 27963392 6464 18446744073709551615 4194304 5895655 140733550291040 140733550286952 5087514 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/11459/statm: 6827 6464 149 416 0 6408 0
Current children cumulated CPU time (s) 0.66
Current children cumulated vsize (KiB) 27308

[startup+1.50024 s]
/proc/loadavg: 0.89 0.94 0.96 2/61 11460
/proc/meminfo: memFree=221732/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=50940 CPUtime=1.46
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 12585 0 0 0 139 7 0 0 20 0 1 0 37929269 52162560 12409 18446744073709551615 4194304 5895655 140733550291040 140733550286360 4234588 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/11459/statm: 12735 12409 164 416 0 12316 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 50940

[startup+3.10027 s]
/proc/loadavg: 0.89 0.94 0.96 2/61 11460
/proc/meminfo: memFree=188376/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=72448 CPUtime=3.06
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 18047 0 0 0 296 10 0 0 20 0 1 0 37929269 74186752 16735 18446744073709551615 4194304 5895655 140733550291040 140733550285896 5094026 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/11459/statm: 18112 16735 195 416 0 17693 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 72448

[startup+6.30023 s]
/proc/loadavg: 0.89 0.94 0.96 2/61 11460
/proc/meminfo: memFree=187260/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=73392 CPUtime=6.23
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 18373 0 0 0 612 11 0 0 20 0 1 0 37929269 75153408 17049 18446744073709551615 4194304 5895655 140733550291040 140733550285896 4446937 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/11459/statm: 18348 17049 195 416 0 17929 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 73392

[startup+12.7003 s]
/proc/loadavg: 0.98 0.95 0.96 2/61 11460
/proc/meminfo: memFree=184408/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=76192 CPUtime=12.58
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 19093 0 0 0 1246 12 0 0 20 0 1 0 37929269 78020608 17746 18446744073709551615 4194304 5895655 140733550291040 140733550285896 4452032 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/11459/statm: 19048 17746 195 416 0 18629 0
Current children cumulated CPU time (s) 12.58
Current children cumulated vsize (KiB) 76192

[startup+25.5003 s]
/proc/loadavg: 0.99 0.96 0.96 2/61 11460
/proc/meminfo: memFree=161964/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=103800 CPUtime=25.24
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 24866 0 0 0 2508 16 0 0 20 0 1 0 37929269 106291200 23489 18446744073709551615 4194304 5895655 140733550291040 140733550285000 4447295 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/11459/statm: 25950 23489 207 416 0 25531 0
Current children cumulated CPU time (s) 25.24
Current children cumulated vsize (KiB) 103800

[startup+51.1002 s]
/proc/loadavg: 0.99 0.96 0.96 2/61 11460
/proc/meminfo: memFree=142124/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=134524 CPUtime=50.72
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 43860 0 0 0 5047 25 0 0 20 0 1 0 37929269 137752576 28138 18446744073709551615 4194304 5895655 140733550291040 140733550285896 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/11459/statm: 33631 28138 208 416 0 33212 0
Current children cumulated CPU time (s) 50.72
Current children cumulated vsize (KiB) 134524

[startup+102.3 s]
/proc/loadavg: 0.99 0.96 0.96 2/61 11460
/proc/meminfo: memFree=41436/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=264752 CPUtime=101.71
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 69092 0 0 0 10125 46 0 0 20 0 1 0 37929269 271106048 53274 18446744073709551615 4194304 5895655 140733550291040 140733550285000 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/11459/statm: 66188 53274 208 416 0 65769 0
Current children cumulated CPU time (s) 101.71
Current children cumulated vsize (KiB) 264752



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+150.9 s]
/proc/loadavg: 0.99 0.97 0.96 2/61 11463
/proc/meminfo: memFree=9596/1022884 swapFree=0/0
[pid=11459] ppid=11458 vsize=346140 CPUtime=150.05
/proc/11459/stat : 11459 (cudf_fumax_bu-0) R 11458 11459 32685 0 -1 4202496 83467 0 0 0 14945 60 0 0 20 0 1 0 37929269 354447360 67603 18446744073709551615 4194304 5895655 140733550291040 140733550285000 4464555 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/11459/statm: 86535 67603 208 416 0 86116 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 346140

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): 150.955
CPU time (s): 150.113
CPU user time (s): 149.481
CPU system time (s): 0.632039
CPU usage (%): 99.4424
Max. virtual memory (cumulated for all children) (KiB): 346140

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.481
system time used= 0.632039
maximum resident set size= 270412
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 83469
page faults= 0
swaps= 0
block input operations= 39640
block output operations= 96
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 17
involuntary context switches= 2238

runsolver used 0.208013 second user time and 0.472029 second system time

The end