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/rand30.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/install/rand30.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/install/rand30.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.86 0.97 1.03 2/64 5048
/proc/meminfo: memFree=290604/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=3152 CPUtime=0
/proc/5048/stat : 5048 (runsolver) R 5047 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115565446 3227648 32 18446744073709551615 134512640 134586868 4291656944 4291654992 4151395376 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5048/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.190324 s]
/proc/loadavg: 0.86 0.97 1.03 2/64 5048
/proc/meminfo: memFree=290604/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=7852 CPUtime=0.13
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 1687 0 0 0 13 0 0 0 20 0 1 0 115565446 8040448 1610 18446744073709551615 4194304 5895655 140735551095472 140735551091384 4410140 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/5048/statm: 1963 1610 149 416 0 1544 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 7852

[startup+0.200362 s]
/proc/loadavg: 0.86 0.97 1.03 2/64 5048
/proc/meminfo: memFree=290604/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=8248 CPUtime=0.14
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 1779 0 0 0 14 0 0 0 20 0 1 0 115565446 8445952 1702 18446744073709551615 4194304 5895655 140735551095472 140735551091384 5130169 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/5048/statm: 2062 1702 149 416 0 1643 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 8248

[startup+0.300312 s]
/proc/loadavg: 0.86 0.97 1.03 2/64 5048
/proc/meminfo: memFree=290604/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=11828 CPUtime=0.24
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 2696 0 0 0 23 1 0 0 20 0 1 0 115565446 12111872 2619 18446744073709551615 4194304 5895655 140735551095472 140735551091384 4348741 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/5048/statm: 2957 2619 149 416 0 2538 0
Current children cumulated CPU time (s) 0.24
Current children cumulated vsize (KiB) 11828

[startup+0.70029 s]
/proc/loadavg: 0.86 0.97 1.03 2/64 5048
/proc/meminfo: memFree=290604/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=24888 CPUtime=0.63
/proc/5048/stat : 5048 (cudf_fumax_bu-0) D 5047 5048 1745 0 -1 4202496 6006 0 0 0 59 4 0 0 20 0 1 0 115565446 25485312 5880 18446744073709551615 4194304 5895655 140735551095472 140735551091384 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/5048/statm: 6222 5880 149 416 0 5803 0
Current children cumulated CPU time (s) 0.63
Current children cumulated vsize (KiB) 24888

[startup+1.50024 s]
/proc/loadavg: 0.86 0.97 1.03 2/65 5049
/proc/meminfo: memFree=242188/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=47156 CPUtime=1.4
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 11605 0 0 0 132 8 0 0 20 0 1 0 115565446 48287744 11430 18446744073709551615 4194304 5895655 140735551095472 140735551091384 5299140 0 0 16781316 16929 0 0 0 17 0 0 0 8 0 0
/proc/5048/statm: 11789 11430 149 416 0 11370 0
Current children cumulated CPU time (s) 1.4
Current children cumulated vsize (KiB) 47156

[startup+3.10026 s]
/proc/loadavg: 0.86 0.97 1.03 2/65 5049
/proc/meminfo: memFree=197384/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=103552 CPUtime=2.98
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 25613 0 0 0 282 16 0 0 20 0 1 0 115565446 106037248 23703 18446744073709551615 4194304 5895655 140735551095472 140735551090328 4455856 0 0 16781316 16929 0 0 0 17 0 0 0 8 0 0
/proc/5048/statm: 25888 23703 195 416 0 25469 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 103552

[startup+6.30026 s]
/proc/loadavg: 0.87 0.97 1.03 2/65 5049
/proc/meminfo: memFree=161540/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=106220 CPUtime=6.15
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 25768 0 0 0 598 17 0 0 20 0 1 0 115565446 108769280 23833 18446744073709551615 4194304 5895655 140735551095472 140735551090328 5085238 0 0 16781316 16929 0 0 0 17 0 0 0 9 0 0
/proc/5048/statm: 26555 23833 195 416 0 26136 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 106220

[startup+12.7003 s]
/proc/loadavg: 0.88 0.97 1.03 2/65 5049
/proc/meminfo: memFree=157696/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=106220 CPUtime=12.48
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 26768 0 0 0 1230 18 0 0 20 0 1 0 115565446 108769280 24776 18446744073709551615 4194304 5895655 140735551095472 140735551090328 5082050 0 0 16781316 16929 0 0 0 17 0 0 0 9 0 0
/proc/5048/statm: 26555 24776 195 416 0 26136 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 106220

[startup+25.5002 s]
/proc/loadavg: 0.91 0.97 1.03 2/65 5049
/proc/meminfo: memFree=157076/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=107152 CPUtime=25.14
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 27108 0 0 0 2494 20 0 0 20 0 1 0 115565446 109723648 25037 18446744073709551615 4194304 5895655 140735551095472 140735551090328 5073438 0 0 16781316 16929 0 0 0 17 0 0 0 13 0 0
/proc/5048/statm: 26788 25037 195 416 0 26369 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 107152

[startup+51.1003 s]
/proc/loadavg: 0.94 0.97 1.02 2/65 5057
/proc/meminfo: memFree=153340/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=109584 CPUtime=50.47
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 27862 0 0 0 5021 26 0 0 20 0 1 0 115565446 112214016 25622 18446744073709551615 4194304 5895655 140735551095472 140735551090328 4451016 0 0 16781316 16929 0 0 0 17 0 0 0 17 0 0
/proc/5048/statm: 27396 25622 195 416 0 26977 0
Current children cumulated CPU time (s) 50.47
Current children cumulated vsize (KiB) 109584

[startup+102.3 s]
/proc/loadavg: 0.97 0.97 1.02 2/65 5057
/proc/meminfo: memFree=139328/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=125816 CPUtime=101.13
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 259864 0 0 0 9987 126 0 0 20 0 1 0 115565446 128835584 29173 18446744073709551615 4194304 5895655 140735551095472 140735551090328 4447009 0 0 16781316 16929 0 0 0 17 0 0 0 31 0 0
/proc/5048/statm: 31454 29173 203 416 0 31035 0
Current children cumulated CPU time (s) 101.13
Current children cumulated vsize (KiB) 125816



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.6 s]
/proc/loadavg: 1.09 1.00 1.03 2/65 5057
/proc/meminfo: memFree=105476/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=176332 CPUtime=150.02
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 281423 0 0 0 14860 142 0 0 20 0 1 0 115565446 180563968 37509 18446744073709551615 4194304 5895655 140735551095472 140735551090328 4447542 0 0 16781316 16929 0 0 0 17 0 0 0 32 0 0
/proc/5048/statm: 44083 37509 208 416 0 43664 0
Current children cumulated CPU time (s) 150.02
Current children cumulated vsize (KiB) 176332

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.6 s]
/proc/loadavg: 1.09 1.00 1.03 2/65 5057
/proc/meminfo: memFree=105476/1022884 swapFree=0/0
[pid=5048] ppid=5047 vsize=176332 CPUtime=150.02
/proc/5048/stat : 5048 (cudf_fumax_bu-0) R 5047 5048 1745 0 -1 4202496 281423 0 0 0 14860 142 0 0 20 0 1 0 115565446 180563968 37509 18446744073709551615 4194304 5895655 140735551095472 140735551090328 4447542 0 0 16781316 16929 0 0 0 17 0 0 0 32 0 0
/proc/5048/statm: 44083 37509 208 416 0 43664 0
Current children cumulated CPU time (s) 150.02
Current children cumulated vsize (KiB) 176332

Child status: 0
Real time (s): 151.662
CPU time (s): 150.085
CPU user time (s): 148.641
CPU system time (s): 1.44409
CPU usage (%): 98.9606
Max. virtual memory (cumulated for all children) (KiB): 187636

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 148.641
system time used= 1.44409
maximum resident set size= 166948
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 281425
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 400
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 56
involuntary context switches= 17209

runsolver used 0.280017 second user time and 0.540033 second system time

The end