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/install/rand96.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/install/rand96.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/install/rand96.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.92 0.95 0.98 2/59 4823
/proc/meminfo: memFree=326728/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=2148 CPUtime=0
/proc/4823/stat : 4823 (cudf_fumax_bu-0) D 4822 4823 1750 0 -1 4202496 244 0 0 0 0 0 0 0 20 0 1 0 115567323 2199552 167 18446744073709551615 4194304 5895655 140733421050144 140733421046056 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/4823/statm: 537 167 135 416 0 118 0

[startup+0.12013 s]
/proc/loadavg: 0.92 0.95 0.98 2/59 4823
/proc/meminfo: memFree=326728/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=6664 CPUtime=0.09
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 1385 0 0 0 8 1 0 0 20 0 1 0 115567323 6823936 1308 18446744073709551615 4194304 5895655 140733421050144 140733421046056 4346709 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/4823/statm: 1666 1308 149 416 0 1247 0
Current children cumulated CPU time (s) 0.09
Current children cumulated vsize (KiB) 6664

[startup+0.200377 s]
/proc/loadavg: 0.92 0.95 0.98 2/59 4823
/proc/meminfo: memFree=326728/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=9632 CPUtime=0.17
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 2149 0 0 0 16 1 0 0 20 0 1 0 115567323 9863168 2072 18446744073709551615 4194304 5895655 140733421050144 140733421046056 4347073 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/4823/statm: 2408 2072 149 416 0 1989 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 9632

[startup+0.300366 s]
/proc/loadavg: 0.92 0.95 0.98 2/59 4823
/proc/meminfo: memFree=326728/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=13280 CPUtime=0.28
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 3051 0 0 0 26 2 0 0 20 0 1 0 115567323 13598720 2974 18446744073709551615 4194304 5895655 140733421050144 140733421046056 4347073 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/4823/statm: 3320 2974 149 416 0 2901 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 13280

[startup+0.700233 s]
/proc/loadavg: 0.92 0.95 0.98 2/59 4823
/proc/meminfo: memFree=326728/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=26868 CPUtime=0.67
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 6496 0 0 0 63 4 0 0 20 0 1 0 115567323 27512832 6370 18446744073709551615 4194304 5895655 140733421050144 140733421046056 5299316 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/4823/statm: 6717 6370 149 416 0 6298 0
Current children cumulated CPU time (s) 0.67
Current children cumulated vsize (KiB) 26868

[startup+1.50024 s]
/proc/loadavg: 0.92 0.95 0.98 2/60 4824
/proc/meminfo: memFree=274220/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=49796 CPUtime=1.45
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 12292 0 0 0 136 9 0 0 20 0 1 0 115567323 50991104 12117 18446744073709551615 4194304 5895655 140733421050144 140733421046056 4346423 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/4823/statm: 12449 12117 149 416 0 12030 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 49796

[startup+3.10023 s]
/proc/loadavg: 0.92 0.95 0.98 2/60 4824
/proc/meminfo: memFree=228424/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=101856 CPUtime=3.03
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 25097 0 0 0 287 16 0 0 20 0 1 0 115567323 104300544 23293 18446744073709551615 4194304 5895655 140733421050144 140733421045000 4436271 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/4823/statm: 25464 23293 195 416 0 25045 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 101856

[startup+6.30024 s]
/proc/loadavg: 0.92 0.95 0.98 2/60 4824
/proc/meminfo: memFree=194316/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=105172 CPUtime=6.18
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 27657 0 0 0 601 17 0 0 20 0 1 0 115567323 107696128 24697 18446744073709551615 4194304 5895655 140733421050144 140733421045000 4447947 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/4823/statm: 26293 24697 195 416 0 25874 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 105172

[startup+12.7003 s]
/proc/loadavg: 0.93 0.96 0.98 2/60 4824
/proc/meminfo: memFree=193820/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=105304 CPUtime=12.5
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 27754 0 0 0 1231 19 0 0 20 0 1 0 115567323 107831296 24787 18446744073709551615 4194304 5895655 140733421050144 140733421045000 4452542 0 0 16781316 16929 0 0 0 17 0 0 0 8 0 0
/proc/4823/statm: 26326 24787 195 416 0 25907 0
Current children cumulated CPU time (s) 12.5
Current children cumulated vsize (KiB) 105304

[startup+25.5003 s]
/proc/loadavg: 0.94 0.96 0.98 2/60 4824
/proc/meminfo: memFree=192580/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=106336 CPUtime=25.19
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 28102 0 0 0 2495 24 0 0 20 0 1 0 115567323 108888064 25069 18446744073709551615 4194304 5895655 140733421050144 140733421045000 4452102 0 0 16781316 16929 0 0 0 17 0 0 0 11 0 0
/proc/4823/statm: 26584 25069 195 416 0 26165 0
Current children cumulated CPU time (s) 25.19
Current children cumulated vsize (KiB) 106336

[startup+51.1003 s]
/proc/loadavg: 0.96 0.96 0.98 2/60 4832
/proc/meminfo: memFree=189092/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=109576 CPUtime=50.5
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 29107 0 0 0 5022 28 0 0 20 0 1 0 115567323 112205824 25857 18446744073709551615 4194304 5895655 140733421050144 140733421045000 5073382 0 0 16781316 16929 0 0 0 17 0 0 0 17 0 0
/proc/4823/statm: 27394 25857 195 416 0 26975 0
Current children cumulated CPU time (s) 50.5
Current children cumulated vsize (KiB) 109576

[startup+102.3 s]
/proc/loadavg: 1.02 0.98 0.98 2/60 4832
/proc/meminfo: memFree=172352/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=126036 CPUtime=101.06
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 33574 0 0 0 10068 38 0 0 20 0 1 0 115567323 129060864 29993 18446744073709551615 4194304 5895655 140733421050144 140733421043944 5073382 0 0 16781316 16929 0 0 0 17 0 0 0 41 0 0
/proc/4823/statm: 31509 29993 195 416 0 31090 0
Current children cumulated CPU time (s) 101.06
Current children cumulated vsize (KiB) 126036



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.7 s]
/proc/loadavg: 1.13 1.01 0.99 2/60 4832
/proc/meminfo: memFree=158464/1022884 swapFree=0/0
[pid=4823] ppid=4822 vsize=139756 CPUtime=150.02
/proc/4823/stat : 4823 (cudf_fumax_bu-0) R 4822 4823 1750 0 -1 4202496 201609 0 0 0 14899 103 0 0 20 0 1 0 115567323 143110144 33435 18446744073709551615 4194304 5895655 140733421050144 140733421043944 4452045 0 0 16781316 16929 0 0 0 17 0 0 0 51 0 0
/proc/4823/statm: 34939 33435 196 416 0 34520 0
Current children cumulated CPU time (s) 150.02
Current children cumulated vsize (KiB) 139756

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): 151.759
CPU time (s): 150.085
CPU user time (s): 149.029
CPU system time (s): 1.05607
CPU usage (%): 98.8974
Max. virtual memory (cumulated for all children) (KiB): 142476

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.029
system time used= 1.05607
maximum resident set size= 140736
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 201611
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 472
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 75
involuntary context switches= 17224

runsolver used 0.248015 second user time and 0.496031 second system time

The end