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/d1583bd8-d489-11df-9a24-00163e3d3b7c.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/d1583bd8-d489-11df-9a24-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/embedded/real/d1583bd8-d489-11df-9a24-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.85 0.95 0.98 2/59 7170
/proc/meminfo: memFree=307320/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=3152 CPUtime=0
/proc/7170/stat : 7170 (runsolver) R 7169 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 116159538 3227648 33 18446744073709551615 134512640 134586868 4293763488 4293761536 4151391280 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/7170/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.126679 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 7170
/proc/meminfo: memFree=307320/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=5328 CPUtime=0.06
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 1049 0 0 0 6 0 0 0 20 0 1 0 116159538 5455872 972 18446744073709551615 4194304 5895655 140735234366640 140735234362552 4410217 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/7170/statm: 1332 972 146 416 0 913 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 5328

[startup+0.200302 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 7170
/proc/meminfo: memFree=307320/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=8364 CPUtime=0.13
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 1809 0 0 0 12 1 0 0 20 0 1 0 116159538 8564736 1732 18446744073709551615 4194304 5895655 140735234366640 140735234362408 4349436 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/7170/statm: 2091 1732 149 416 0 1672 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 8364

[startup+0.300306 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 7170
/proc/meminfo: memFree=307320/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=12004 CPUtime=0.23
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 2724 0 0 0 21 2 0 0 20 0 1 0 116159538 12292096 2647 18446744073709551615 4194304 5895655 140735234366640 140735234362552 5299332 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/7170/statm: 3001 2647 149 416 0 2582 0
Current children cumulated CPU time (s) 0.23
Current children cumulated vsize (KiB) 12004

[startup+0.700217 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 7170
/proc/meminfo: memFree=307320/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=25592 CPUtime=0.62
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 6193 0 0 0 59 3 0 0 20 0 1 0 116159538 26206208 6067 18446744073709551615 4194304 5895655 140735234366640 140735234362552 4347361 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/7170/statm: 6398 6067 149 416 0 5979 0
Current children cumulated CPU time (s) 0.62
Current children cumulated vsize (KiB) 25592

[startup+1.50024 s]
/proc/loadavg: 0.85 0.95 0.98 2/60 7171
/proc/meminfo: memFree=257828/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=49152 CPUtime=1.36
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 12136 0 0 0 130 6 0 0 20 0 1 0 116159538 50331648 11961 18446744073709551615 4194304 5895655 140735234366640 140735234361944 4276772 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/7170/statm: 12288 11961 154 416 0 11869 0
Current children cumulated CPU time (s) 1.36
Current children cumulated vsize (KiB) 49152

[startup+3.10027 s]
/proc/loadavg: 0.85 0.95 0.98 2/60 7171
/proc/meminfo: memFree=221372/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=72448 CPUtime=2.95
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 18045 0 0 0 287 8 0 0 20 0 1 0 116159538 74186752 16734 18446744073709551615 4194304 5895655 140735234366640 140735234361496 4451677 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/7170/statm: 18112 16734 195 416 0 17693 0
Current children cumulated CPU time (s) 2.95
Current children cumulated vsize (KiB) 72448

[startup+6.30026 s]
/proc/loadavg: 0.86 0.95 0.98 2/60 7171
/proc/meminfo: memFree=220504/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=73128 CPUtime=6.11
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 18269 0 0 0 602 9 0 0 20 0 1 0 116159538 74883072 16950 18446744073709551615 4194304 5895655 140735234366640 140735234361496 4468639 0 0 16781316 16929 0 0 0 17 0 0 0 13 0 0
/proc/7170/statm: 18282 16950 195 416 0 17863 0
Current children cumulated CPU time (s) 6.11
Current children cumulated vsize (KiB) 73128

[startup+12.7002 s]
/proc/loadavg: 0.87 0.95 0.98 2/60 7171
/proc/meminfo: memFree=218024/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=75664 CPUtime=12.38
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 18863 0 0 0 1226 12 0 0 20 0 1 0 116159538 77479936 17530 18446744073709551615 4194304 5895655 140735234366640 140735234361496 4452602 0 0 16781316 16929 0 0 0 17 0 0 0 20 0 0
/proc/7170/statm: 18916 17530 195 416 0 18497 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 75664

[startup+25.5002 s]
/proc/loadavg: 0.90 0.95 0.98 2/60 7171
/proc/meminfo: memFree=207236/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=84988 CPUtime=25
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 21586 0 0 0 2483 17 0 0 20 0 1 0 116159538 87027712 20225 18446744073709551615 4194304 5895655 140735234366640 140735234361496 5081866 0 0 16781316 16929 0 0 0 17 0 0 0 27 0 0
/proc/7170/statm: 21247 20225 206 416 0 20828 0
Current children cumulated CPU time (s) 25
Current children cumulated vsize (KiB) 84988

[startup+51.1002 s]
/proc/loadavg: 0.93 0.95 0.98 2/60 7171
/proc/meminfo: memFree=174996/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=134524 CPUtime=50.43
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 43848 0 0 0 5014 29 0 0 20 0 1 0 116159538 137752576 28127 18446744073709551615 4194304 5895655 140735234366640 140735234361496 4462155 0 0 16781316 16929 0 0 0 17 0 0 0 27 0 0
/proc/7170/statm: 33631 28127 208 416 0 33212 0
Current children cumulated CPU time (s) 50.43
Current children cumulated vsize (KiB) 134524

[startup+102.3 s]
/proc/loadavg: 1.02 0.97 0.99 2/60 7174
/proc/meminfo: memFree=78028/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=264752 CPUtime=101.3
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 67951 0 0 0 10083 47 0 0 20 0 1 0 116159538 271106048 52141 18446744073709551615 4194304 5895655 140735234366640 140735234360600 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 27 0 0
/proc/7170/statm: 66188 52141 208 416 0 65769 0
Current children cumulated CPU time (s) 101.3
Current children cumulated vsize (KiB) 264752



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.4 s]
/proc/loadavg: 1.01 0.97 0.99 2/60 7174
/proc/meminfo: memFree=15656/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=346140 CPUtime=150.08
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 83534 0 0 0 14947 61 0 0 20 0 1 0 116159538 354447360 67670 18446744073709551615 4194304 5895655 140735234366640 140735234360600 4447267 0 0 16781316 16929 0 0 0 17 0 0 0 27 0 0
/proc/7170/statm: 86535 67670 208 416 0 86116 0
Current children cumulated CPU time (s) 150.08
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

[startup+151.4 s]
/proc/loadavg: 1.01 0.97 0.99 2/60 7174
/proc/meminfo: memFree=15656/1022884 swapFree=0/0
[pid=7170] ppid=7169 vsize=346140 CPUtime=150.08
/proc/7170/stat : 7170 (cudf_fumax_bu-0) R 7169 7170 1750 0 -1 4202496 83534 0 0 0 14947 61 0 0 20 0 1 0 116159538 354447360 67670 18446744073709551615 4194304 5895655 140735234366640 140735234360600 4447267 0 0 16781316 16929 0 0 0 17 0 0 0 27 0 0
/proc/7170/statm: 86535 67670 208 416 0 86116 0
Current children cumulated CPU time (s) 150.08
Current children cumulated vsize (KiB) 346140

Child status: 0
Real time (s): 151.446
CPU time (s): 150.133
CPU user time (s): 149.505
CPU system time (s): 0.628039
CPU usage (%): 99.1336
Max. virtual memory (cumulated for all children) (KiB): 346140

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.505
system time used= 0.628039
maximum resident set size= 270680
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 83536
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= 25
involuntary context switches= 17189

runsolver used 0.240015 second user time and 0.444027 second system time

The end