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/e0bd67a6-56d0-11df-b11f-00163e7a6f5e.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/e0bd67a6-56d0-11df-b11f-00163e7a6f5e.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/real/e0bd67a6-56d0-11df-b11f-00163e7a6f5e.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.89 0.95 1.00 2/60 8663
/proc/meminfo: memFree=238196/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=3152 CPUtime=0
/proc/8663/stat : 8663 (runsolver) R 8662 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 37357492 3227648 32 18446744073709551615 134512640 134586868 4287956976 4287955024 4151440432 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/8663/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.207209 s]
/proc/loadavg: 0.89 0.95 1.00 2/60 8663
/proc/meminfo: memFree=238196/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=10420 CPUtime=0.2
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 2327 0 0 0 18 2 0 0 20 0 1 0 37357492 10670080 2249 18446744073709551615 4194304 5895655 140734888077040 140734888072952 5303556 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8663/statm: 2605 2249 149 416 0 2186 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 10420

[startup+0.300324 s]
/proc/loadavg: 0.89 0.95 1.00 2/60 8663
/proc/meminfo: memFree=238196/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=13852 CPUtime=0.29
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 3193 0 0 0 27 2 0 0 20 0 1 0 37357492 14184448 3115 18446744073709551615 4194304 5895655 140734888077040 140734888072952 4899073 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8663/statm: 3463 3115 149 416 0 3044 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 13852

[startup+0.40031 s]
/proc/loadavg: 0.89 0.95 1.00 2/60 8663
/proc/meminfo: memFree=238196/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=17876 CPUtime=0.39
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 4209 0 0 0 37 2 0 0 20 0 1 0 37357492 18305024 4131 18446744073709551615 4194304 5895655 140734888077040 140734888072952 4346926 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8663/statm: 4469 4131 149 416 0 4050 0
Current children cumulated CPU time (s) 0.39
Current children cumulated vsize (KiB) 17876

[startup+0.700258 s]
/proc/loadavg: 0.89 0.95 1.00 2/60 8663
/proc/meminfo: memFree=238196/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=28908 CPUtime=0.69
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 7019 0 0 0 65 4 0 0 20 0 1 0 37357492 29601792 6892 18446744073709551615 4194304 5895655 140734888077040 140734888072952 4346937 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8663/statm: 7227 6892 149 416 0 6808 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 28908

[startup+1.50027 s]
/proc/loadavg: 0.89 0.95 1.00 2/61 8664
/proc/meminfo: memFree=198872/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=47548 CPUtime=1.48
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 10578 0 0 0 142 6 0 0 20 0 1 0 37357492 48689152 10044 18446744073709551615 4194304 5895655 140734888077040 140734888071896 4473034 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8663/statm: 11887 10044 195 416 0 11468 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 47548

[startup+3.10024 s]
/proc/loadavg: 0.89 0.95 1.00 2/61 8664
/proc/meminfo: memFree=198748/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=47548 CPUtime=3.07
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 10602 0 0 0 301 6 0 0 20 0 1 0 37357492 48689152 10067 18446744073709551615 4194304 5895655 140734888077040 140734888071896 5094903 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8663/statm: 11887 10067 195 416 0 11468 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 47548

[startup+6.30021 s]
/proc/loadavg: 0.90 0.96 1.00 2/61 8664
/proc/meminfo: memFree=198252/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=47548 CPUtime=6.25
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 10714 0 0 0 616 9 0 0 20 0 1 0 37357492 48689152 10167 18446744073709551615 4194304 5895655 140734888077040 140734888071896 5081931 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8663/statm: 11887 10167 195 416 0 11468 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 47548

[startup+12.7002 s]
/proc/loadavg: 0.91 0.96 1.00 2/61 8664
/proc/meminfo: memFree=197508/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=47548 CPUtime=12.61
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 11235 0 0 0 1250 11 0 0 20 0 1 0 37357492 48689152 10643 18446744073709551615 4194304 5895655 140734888077040 140734888071896 4452845 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/8663/statm: 11887 10643 195 416 0 11468 0
Current children cumulated CPU time (s) 12.61
Current children cumulated vsize (KiB) 47548

Solver just ended. Dumping a history of the last processes samples

[startup+12.9003 s]
/proc/loadavg: 0.91 0.96 1.00 2/61 8664
/proc/meminfo: memFree=197508/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=47548 CPUtime=12.81
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 11268 0 0 0 1270 11 0 0 20 0 1 0 37357492 48689152 10666 18446744073709551615 4194304 5895655 140734888077040 140734888071896 5081866 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/8663/statm: 11887 10666 195 416 0 11468 0
Current children cumulated CPU time (s) 12.81
Current children cumulated vsize (KiB) 47548

[startup+13.7002 s]
/proc/loadavg: 0.91 0.96 1.00 2/61 8664
/proc/meminfo: memFree=196144/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=47548 CPUtime=13.6
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 11269 0 0 0 1348 12 0 0 20 0 1 0 37357492 48689152 10667 18446744073709551615 4194304 5895655 140734888077040 140734888071896 5093846 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/8663/statm: 11887 10667 195 416 0 11468 0
Current children cumulated CPU time (s) 13.6
Current children cumulated vsize (KiB) 47548

[startup+13.9002 s]
/proc/loadavg: 0.91 0.96 1.00 2/61 8664
/proc/meminfo: memFree=196144/1022884 swapFree=0/0
[pid=8663] ppid=8662 vsize=47548 CPUtime=13.8
/proc/8663/stat : 8663 (cudf_fumax_bu-0) R 8662 8663 32685 0 -1 4202496 11269 0 0 0 1368 12 0 0 20 0 1 0 37357492 48689152 10667 18446744073709551615 4194304 5895655 140734888077040 140734888071896 4452593 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/8663/statm: 11887 10667 195 416 0 11468 0
Current children cumulated CPU time (s) 13.8
Current children cumulated vsize (KiB) 47548

Child status: 0
Real time (s): 13.9781
CPU time (s): 13.8849
CPU user time (s): 13.7289
CPU system time (s): 0.156009
CPU usage (%): 99.3333
Max. virtual memory (cumulated for all children) (KiB): 47548

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.7289
system time used= 0.156009
maximum resident set size= 42836
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 11313
page faults= 0
swaps= 0
block input operations= 0
block output operations= 328
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 5
involuntary context switches= 204

runsolver used 0.040002 second user time and 0.040002 second system time

The end