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/ec32fc68-7254-11e0-8436-00163e1e087d.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/ec32fc68-7254-11e0-8436-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/real/ec32fc68-7254-11e0-8436-00163e1e087d.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.85 0.93 0.97 2/60 8714
/proc/meminfo: memFree=165688/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=3152 CPUtime=0
/proc/8714/stat : 8714 (runsolver) R 8713 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 37419763 3227648 32 18446744073709551615 134512640 134586868 4294308992 4294307040 4152153136 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/8714/statm: 788 32 0 19 0 73 0

[startup+0.198653 s]
/proc/loadavg: 0.85 0.93 0.97 2/60 8714
/proc/meminfo: memFree=165688/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=16296 CPUtime=0.19
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 3814 0 0 0 18 1 0 0 20 0 1 0 37419763 16687104 3736 18446744073709551615 4194304 5895655 140736387607632 140736387603544 4348122 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8714/statm: 4074 3736 149 416 0 3655 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 16296

[startup+0.200263 s]
/proc/loadavg: 0.85 0.93 0.97 2/60 8714
/proc/meminfo: memFree=165688/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=16428 CPUtime=0.19
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 3835 0 0 0 18 1 0 0 20 0 1 0 37419763 16822272 3757 18446744073709551615 4194304 5895655 140736387607632 140736387603544 5107386 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8714/statm: 4107 3757 149 416 0 3688 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 16428

[startup+0.300194 s]
/proc/loadavg: 0.85 0.93 0.97 2/60 8714
/proc/meminfo: memFree=165688/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=22756 CPUtime=0.29
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 5464 0 0 0 28 1 0 0 20 0 1 0 37419763 23302144 5337 18446744073709551615 4194304 5895655 140736387607632 140736387603544 5087514 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8714/statm: 5689 5337 149 416 0 5270 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 22756

[startup+0.7002 s]
/proc/loadavg: 0.85 0.93 0.97 2/60 8714
/proc/meminfo: memFree=165688/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=45680 CPUtime=0.69
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 11311 0 0 0 66 3 0 0 20 0 1 0 37419763 46776320 11038 18446744073709551615 4194304 5895655 140736387607632 140736387603240 4370720 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8714/statm: 11420 11038 166 416 0 11001 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 45680

[startup+1.5002 s]
/proc/loadavg: 0.85 0.93 0.97 2/61 8715
/proc/meminfo: memFree=111608/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=61572 CPUtime=1.48
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 14353 0 0 0 144 4 0 0 20 0 1 0 37419763 63049728 13717 18446744073709551615 4194304 5895655 140736387607632 140736387602488 4452480 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8714/statm: 15393 13717 195 416 0 14974 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 61572

[startup+3.10022 s]
/proc/loadavg: 0.86 0.93 0.97 2/61 8715
/proc/meminfo: memFree=111484/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=61572 CPUtime=3.08
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 14371 0 0 0 303 5 0 0 20 0 1 0 37419763 63049728 13731 18446744073709551615 4194304 5895655 140736387607632 140736387602488 5093541 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/8714/statm: 15393 13731 195 416 0 14974 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 61572

[startup+6.30025 s]
/proc/loadavg: 0.86 0.93 0.97 2/61 8715
/proc/meminfo: memFree=110864/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=61572 CPUtime=6.24
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 14548 0 0 0 618 6 0 0 20 0 1 0 37419763 63049728 13881 18446744073709551615 4194304 5895655 140736387607632 140736387602488 4436174 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/8714/statm: 15393 13881 195 416 0 14974 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 61572

[startup+12.7002 s]
/proc/loadavg: 0.88 0.93 0.97 2/61 8715
/proc/meminfo: memFree=110616/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=61572 CPUtime=12.6
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 14558 0 0 0 1252 8 0 0 20 0 1 0 37419763 63049728 13891 18446744073709551615 4194304 5895655 140736387607632 140736387602488 5093846 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/8714/statm: 15393 13891 195 416 0 14974 0
Current children cumulated CPU time (s) 12.6
Current children cumulated vsize (KiB) 61572

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

[startup+12.8003 s]
/proc/loadavg: 0.88 0.93 0.97 2/61 8715
/proc/meminfo: memFree=110616/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=61572 CPUtime=12.7
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 14558 0 0 0 1262 8 0 0 20 0 1 0 37419763 63049728 13891 18446744073709551615 4194304 5895655 140736387607632 140736387602488 5093533 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/8714/statm: 15393 13891 195 416 0 14974 0
Current children cumulated CPU time (s) 12.7
Current children cumulated vsize (KiB) 61572

[startup+19.2002 s]
/proc/loadavg: 0.89 0.93 0.97 2/61 8715
/proc/meminfo: memFree=110368/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=61572 CPUtime=19.05
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 14648 0 0 0 1895 10 0 0 20 0 1 0 37419763 63049728 13962 18446744073709551615 4194304 5895655 140736387607632 140736387602488 5084973 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/8714/statm: 15393 13962 195 416 0 14974 0
Current children cumulated CPU time (s) 19.05
Current children cumulated vsize (KiB) 61572

[startup+22.4003 s]
/proc/loadavg: 0.90 0.93 0.97 2/61 8715
/proc/meminfo: memFree=109748/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=61956 CPUtime=22.22
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 14796 0 0 0 2211 11 0 0 20 0 1 0 37419763 63442944 14075 18446744073709551615 4194304 5895655 140736387607632 140736387602488 4448187 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/8714/statm: 15489 14075 195 416 0 15070 0
Current children cumulated CPU time (s) 22.22
Current children cumulated vsize (KiB) 61956

[startup+24.0003 s]
/proc/loadavg: 0.90 0.93 0.97 2/61 8715
/proc/meminfo: memFree=109748/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=61956 CPUtime=23.82
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 14809 0 0 0 2370 12 0 0 20 0 1 0 37419763 63442944 14087 18446744073709551615 4194304 5895655 140736387607632 140736387602488 4452880 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/8714/statm: 15489 14087 195 416 0 15070 0
Current children cumulated CPU time (s) 23.82
Current children cumulated vsize (KiB) 61956

[startup+24.8002 s]
/proc/loadavg: 0.90 0.93 0.97 2/61 8715
/proc/meminfo: memFree=109004/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=62632 CPUtime=24.61
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 15033 0 0 0 2449 12 0 0 20 0 1 0 37419763 64135168 14311 18446744073709551615 4194304 5895655 140736387607632 140736387602488 4452673 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/8714/statm: 15658 14311 195 416 0 15239 0
Current children cumulated CPU time (s) 24.61
Current children cumulated vsize (KiB) 62632

[startup+25.2002 s]
/proc/loadavg: 0.90 0.93 0.97 2/61 8715
/proc/meminfo: memFree=109004/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=62632 CPUtime=25.01
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 15033 0 0 0 2489 12 0 0 20 0 1 0 37419763 64135168 14311 18446744073709551615 4194304 5895655 140736387607632 140736387602488 4455730 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/8714/statm: 15658 14311 195 416 0 15239 0
Current children cumulated CPU time (s) 25.01
Current children cumulated vsize (KiB) 62632

[startup+25.4088 s]
/proc/loadavg: 0.90 0.93 0.97 2/61 8715
/proc/meminfo: memFree=108880/1022884 swapFree=0/0
[pid=8714] ppid=8713 vsize=62632 CPUtime=25.21
/proc/8714/stat : 8714 (cudf_fumax_bu-0) R 8713 8714 32685 0 -1 4202496 15033 0 0 0 2509 12 0 0 20 0 1 0 37419763 64135168 14311 18446744073709551615 4194304 5895655 140736387607632 140736387602488 5093533 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/8714/statm: 15658 14311 195 416 0 15239 0
Current children cumulated CPU time (s) 25.21
Current children cumulated vsize (KiB) 62632

Child status: 0
Real time (s): 25.4995
CPU time (s): 25.3136
CPU user time (s): 25.1496
CPU system time (s): 0.16401
CPU usage (%): 99.2708
Max. virtual memory (cumulated for all children) (KiB): 62632

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 25.1496
system time used= 0.16401
maximum resident set size= 57328
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 15056
page faults= 0
swaps= 0
block input operations= 0
block output operations= 400
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 9
involuntary context switches= 387

runsolver used 0.048003 second user time and 0.092005 second system time

The end