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/adf7b774-9af8-11df-bc37-00163e46d37a.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/adf7b774-9af8-11df-bc37-00163e46d37a.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/real/adf7b774-9af8-11df-bc37-00163e46d37a.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.85 0.95 0.98 2/59 5169
/proc/meminfo: memFree=201392/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=3152 CPUtime=0
/proc/5169/stat : 5169 (runsolver) R 5168 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115678652 3227648 32 18446744073709551615 134512640 134586868 4292770272 4292768320 4152075312 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5169/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.175211 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 5169
/proc/meminfo: memFree=201392/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=9212 CPUtime=0.16
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 2033 0 0 0 14 2 0 0 20 0 1 0 115678652 9433088 1956 18446744073709551615 4194304 5895655 140735232533616 140735232529528 4408429 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/5169/statm: 2303 1956 149 416 0 1884 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 9212

[startup+0.200354 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 5169
/proc/meminfo: memFree=201392/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=10136 CPUtime=0.18
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 2280 0 0 0 16 2 0 0 20 0 1 0 115678652 10379264 2203 18446744073709551615 4194304 5895655 140735232533616 140735232529528 4410157 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/5169/statm: 2534 2203 149 416 0 2115 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 10136

[startup+0.30034 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 5169
/proc/meminfo: memFree=201392/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=14032 CPUtime=0.28
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 3228 0 0 0 25 3 0 0 20 0 1 0 115678652 14368768 3151 18446744073709551615 4194304 5895655 140735232533616 140735232529528 4348800 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/5169/statm: 3508 3151 149 416 0 3089 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 14032

[startup+0.70023 s]
/proc/loadavg: 0.85 0.95 0.98 2/59 5169
/proc/meminfo: memFree=201392/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=27620 CPUtime=0.67
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 6701 0 0 0 62 5 0 0 20 0 1 0 115678652 28282880 6575 18446744073709551615 4194304 5895655 140735232533616 140735232529528 4346709 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/5169/statm: 6905 6575 149 416 0 6486 0
Current children cumulated CPU time (s) 0.67
Current children cumulated vsize (KiB) 27620

[startup+1.50024 s]
/proc/loadavg: 0.85 0.95 0.98 2/60 5170
/proc/meminfo: memFree=147684/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=59628 CPUtime=1.45
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 14164 0 0 0 136 9 0 0 20 0 1 0 115678652 61059072 13568 18446744073709551615 4194304 5895655 140735232533616 140735232527400 5130443 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/5169/statm: 14907 13568 194 416 0 14488 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 59628

[startup+3.10025 s]
/proc/loadavg: 0.85 0.95 0.98 2/60 5170
/proc/meminfo: memFree=126604/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=62388 CPUtime=3.04
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 14795 0 0 0 293 11 0 0 20 0 1 0 115678652 63885312 14147 18446744073709551615 4194304 5895655 140735232533616 140735232528472 4436174 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/5169/statm: 15597 14147 195 416 0 15178 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 62388

[startup+6.30024 s]
/proc/loadavg: 0.86 0.95 0.98 2/60 5170
/proc/meminfo: memFree=126480/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=62388 CPUtime=6.22
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 14824 0 0 0 610 12 0 0 20 0 1 0 115678652 63885312 14175 18446744073709551615 4194304 5895655 140735232533616 140735232528472 5085377 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/5169/statm: 15597 14175 195 416 0 15178 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 62388

[startup+12.7002 s]
/proc/loadavg: 0.87 0.96 0.98 2/60 5170
/proc/meminfo: memFree=124992/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=62388 CPUtime=12.55
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 15163 0 0 0 1239 16 0 0 20 0 1 0 115678652 63885312 14489 18446744073709551615 4194304 5895655 140735232533616 140735232528472 4452854 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5169/statm: 15597 14489 195 416 0 15178 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 62388

[startup+25.5002 s]
/proc/loadavg: 0.90 0.96 0.98 2/60 5170
/proc/meminfo: memFree=109368/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=79112 CPUtime=25.22
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 19398 0 0 0 2501 21 0 0 20 0 1 0 115678652 81010688 18671 18446744073709551615 4194304 5895655 140735232533616 140735232527576 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/5169/statm: 19778 18671 206 416 0 19359 0
Current children cumulated CPU time (s) 25.22
Current children cumulated vsize (KiB) 79112

[startup+51.1002 s]
/proc/loadavg: 0.93 0.96 0.98 2/60 5170
/proc/meminfo: memFree=84444/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=117100 CPUtime=50.64
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 43847 0 0 0 5019 45 0 0 20 0 1 0 115678652 119910400 24463 18446744073709551615 4194304 5895655 140735232533616 140735232527624 4447546 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/5169/statm: 29275 24463 206 416 0 28856 0
Current children cumulated CPU time (s) 50.64
Current children cumulated vsize (KiB) 117100

[startup+102.3 s]
/proc/loadavg: 0.97 0.96 0.98 2/60 5170
/proc/meminfo: memFree=17856/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=203204 CPUtime=101.5
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 112053 0 0 0 10053 97 0 0 20 0 1 0 115678652 208080896 41194 18446744073709551615 4194304 5895655 140735232533616 140735232527576 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/5169/statm: 50801 41194 207 416 0 50382 0
Current children cumulated CPU time (s) 101.5
Current children cumulated vsize (KiB) 203204



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.2 s]
/proc/loadavg: 0.98 0.97 0.98 2/60 5170
/proc/meminfo: memFree=48608/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=174152 CPUtime=150.05
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 143831 0 0 0 14891 114 0 0 20 0 1 0 115678652 178331648 38713 18446744073709551615 4194304 5895655 140735232533616 140735232527336 4447016 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/5169/statm: 43538 38713 207 416 0 43119 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 174152

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.98 0.97 0.98 2/60 5170
/proc/meminfo: memFree=48608/1022884 swapFree=0/0
[pid=5169] ppid=5168 vsize=174152 CPUtime=150.05
/proc/5169/stat : 5169 (cudf_fumax_bu-0) R 5168 5169 1750 0 -1 4202496 143831 0 0 0 14891 114 0 0 20 0 1 0 115678652 178331648 38713 18446744073709551615 4194304 5895655 140735232533616 140735232527336 4447016 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/5169/statm: 43538 38713 207 416 0 43119 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 174152

Child status: 0
Real time (s): 151.255
CPU time (s): 150.113
CPU user time (s): 148.953
CPU system time (s): 1.16007
CPU usage (%): 99.2452
Max. virtual memory (cumulated for all children) (KiB): 204972

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.953
system time used= 1.16007
maximum resident set size= 194268
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 143834
page faults= 0
swaps= 0
block input operations= 37880
block output operations= 280
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 17
involuntary context switches= 17171

runsolver used 0.200012 second user time and 0.48403 second system time

The end