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/rand242.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/install/rand242.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/install/rand242.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: 1.53 1.41 1.14 2/60 8486
/proc/meminfo: memFree=460336/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=3152 CPUtime=0
/proc/8486/stat : 8486 (runsolver) R 8485 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 37271567 3227648 32 18446744073709551615 134512640 134586868 4293939920 4293937968 4152149040 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/8486/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.134648 s]
/proc/loadavg: 1.53 1.41 1.14 2/60 8486
/proc/meminfo: memFree=460336/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=3732 CPUtime=0.02
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 654 0 16 0 2 0 0 0 20 0 1 0 37271567 3821568 592 18446744073709551615 4194304 5895655 140733795473504 140733795469416 4347073 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/8486/statm: 933 592 146 416 0 514 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 3732

[startup+0.200287 s]
/proc/loadavg: 1.53 1.41 1.14 2/60 8486
/proc/meminfo: memFree=460336/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=7192 CPUtime=0.07
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 1526 0 16 0 6 1 0 0 20 0 1 0 37271567 7364608 1464 18446744073709551615 4194304 5895655 140733795473504 140733795469416 4983824 0 0 16781316 16929 0 0 0 17 0 0 0 12 0 0
/proc/8486/statm: 1798 1464 149 416 0 1379 0
Current children cumulated CPU time (s) 0.07
Current children cumulated vsize (KiB) 7192

[startup+0.300279 s]
/proc/loadavg: 1.53 1.41 1.14 2/60 8486
/proc/meminfo: memFree=460336/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=13016 CPUtime=0.17
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 2957 0 16 0 15 2 0 0 20 0 1 0 37271567 13328384 2895 18446744073709551615 4194304 5895655 140733795473504 140733795469416 4410140 0 0 16781316 16929 0 0 0 17 0 0 0 12 0 0
/proc/8486/statm: 3254 2895 149 416 0 2835 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 13016

[startup+0.70026 s]
/proc/loadavg: 1.53 1.41 1.14 2/60 8486
/proc/meminfo: memFree=460336/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=26472 CPUtime=0.56
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 6381 0 16 0 52 4 0 0 20 0 1 0 37271567 27107328 6270 18446744073709551615 4194304 5895655 140733795473504 140733795469416 4346931 0 0 16781316 16929 0 0 0 17 0 0 0 13 0 0
/proc/8486/statm: 6618 6270 149 416 0 6199 0
Current children cumulated CPU time (s) 0.56
Current children cumulated vsize (KiB) 26472

[startup+1.50024 s]
/proc/loadavg: 1.53 1.41 1.14 2/61 8487
/proc/meminfo: memFree=407124/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=49400 CPUtime=1.35
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 12168 0 16 0 128 7 0 0 20 0 1 0 37271567 50585600 12008 18446744073709551615 4194304 5895655 140733795473504 140733795469416 4347104 0 0 16781316 16929 0 0 0 17 0 0 0 13 0 0
/proc/8486/statm: 12350 12008 149 416 0 11931 0
Current children cumulated CPU time (s) 1.35
Current children cumulated vsize (KiB) 49400

[startup+3.10025 s]
/proc/loadavg: 1.53 1.41 1.14 2/61 8487
/proc/meminfo: memFree=359136/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=102660 CPUtime=2.91
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 25281 0 17 0 278 13 0 0 20 0 1 0 37271567 105123840 23438 18446744073709551615 4194304 5895655 140733795473504 140733795468360 5095021 0 0 16781316 16929 0 0 0 17 0 0 0 16 0 0
/proc/8486/statm: 25665 23438 195 416 0 25246 0
Current children cumulated CPU time (s) 2.91
Current children cumulated vsize (KiB) 102660

[startup+6.30025 s]
/proc/loadavg: 1.48 1.40 1.14 2/61 8487
/proc/meminfo: memFree=325408/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=107296 CPUtime=6.07
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 26921 0 17 0 593 14 0 0 20 0 1 0 37271567 109871104 24923 18446744073709551615 4194304 5895655 140733795473504 140733795468360 4468936 0 0 16781316 16929 0 0 0 17 0 0 0 18 0 0
/proc/8486/statm: 26824 24923 195 416 0 26405 0
Current children cumulated CPU time (s) 6.07
Current children cumulated vsize (KiB) 107296

[startup+12.7002 s]
/proc/loadavg: 1.45 1.40 1.13 2/61 8487
/proc/meminfo: memFree=325284/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=107296 CPUtime=12.32
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 26932 0 17 0 1218 14 0 0 20 0 1 0 37271567 109871104 24932 18446744073709551615 4194304 5895655 140733795473504 140733795468360 5073222 0 0 16781316 16929 0 0 0 17 0 0 0 29 0 0
/proc/8486/statm: 26824 24932 195 416 0 26405 0
Current children cumulated CPU time (s) 12.32
Current children cumulated vsize (KiB) 107296

[startup+25.5003 s]
/proc/loadavg: 1.35 1.38 1.13 2/61 8487
/proc/meminfo: memFree=324664/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=107776 CPUtime=25.04
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 27127 0 17 0 2486 18 0 0 20 0 1 0 37271567 110362624 25076 18446744073709551615 4194304 5895655 140733795473504 140733795468360 4452272 0 0 16781316 16929 0 0 0 17 0 0 0 32 0 0
/proc/8486/statm: 26944 25076 195 416 0 26525 0
Current children cumulated CPU time (s) 25.04
Current children cumulated vsize (KiB) 107776

[startup+51.1003 s]
/proc/loadavg: 1.31 1.36 1.13 2/61 8487
/proc/meminfo: memFree=320696/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=111980 CPUtime=50.43
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 28422 0 17 0 5021 22 0 0 20 0 1 0 37271567 114667520 26062 18446744073709551615 4194304 5895655 140733795473504 140733795468360 5082048 0 0 16781316 16929 0 0 0 17 0 0 0 40 0 0
/proc/8486/statm: 27995 26062 195 416 0 27576 0
Current children cumulated CPU time (s) 50.43
Current children cumulated vsize (KiB) 111980

[startup+102.3 s]
/proc/loadavg: 1.13 1.30 1.12 2/61 8487
/proc/meminfo: memFree=307180/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=126000 CPUtime=101.17
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 31764 0 17 0 10089 28 0 0 20 0 1 0 37271567 129024000 29378 18446744073709551615 4194304 5895655 140733795473504 140733795468360 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 58 0 0
/proc/8486/statm: 31500 29378 195 416 0 31081 0
Current children cumulated CPU time (s) 101.17
Current children cumulated vsize (KiB) 126000



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.5 s]
/proc/loadavg: 1.06 1.25 1.11 2/61 8487
/proc/meminfo: memFree=285108/1022884 swapFree=0/0
[pid=8486] ppid=8485 vsize=146152 CPUtime=150.02
/proc/8486/stat : 8486 (cudf_fumax_bu-0) R 8485 8486 32685 0 -1 4202496 38456 0 17 0 14964 38 0 0 20 0 1 0 37271567 149659648 34832 18446744073709551615 4194304 5895655 140733795473504 140733795468360 4473028 0 0 16781316 16929 0 0 0 17 0 0 0 68 0 0
/proc/8486/statm: 36538 34832 196 416 0 36119 0
Current children cumulated CPU time (s) 150.02
Current children cumulated vsize (KiB) 146152

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.567
CPU time (s): 150.097
CPU user time (s): 149.685
CPU system time (s): 0.412025
CPU usage (%): 99.0306
Max. virtual memory (cumulated for all children) (KiB): 146152

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.685
system time used= 0.412025
maximum resident set size= 139328
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 38458
page faults= 17
swaps= 0
block input operations= 71536
block output operations= 448
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 106
involuntary context switches= 2268

runsolver used 0.248015 second user time and 0.540033 second system time

The end