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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/huge1.cudf.cudf_set.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/cudf_set//huge1.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/huge1.cudf.cudf_set.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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: 1.12 0.69 0.29 2/43 4394
/proc/meminfo: memFree=392172/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=3024 CPUtime=0
/proc/4394/stat : 4394 (runsolver) D 4393 4394 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 877526309 3096576 93 1283457024 134512640 134586868 4288965568 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/4394/statm: 756 93 62 19 0 54 0

[startup+0.197503 s]
/proc/loadavg: 1.12 0.69 0.29 2/43 4394
/proc/meminfo: memFree=392172/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 2217 0 0 0 0 0 0 25 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2604

[startup+0.205522 s]
/proc/loadavg: 1.12 0.69 0.29 2/43 4394
/proc/meminfo: memFree=392172/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 2217 0 0 0 0 0 0 25 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2604

[startup+0.305485 s]
/proc/loadavg: 1.12 0.69 0.29 2/43 4394
/proc/meminfo: memFree=392172/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 2217 0 0 0 0 0 0 25 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2604

[startup+0.70553 s]
/proc/loadavg: 1.12 0.69 0.29 2/43 4394
/proc/meminfo: memFree=392172/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
Current children cumulated CPU time (s) 0.35
Current children cumulated vsize (KiB) 2604

[startup+1.50888 s]
/proc/loadavg: 1.27 0.73 0.31 2/45 4408
/proc/meminfo: memFree=380436/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=8804 CPUtime=0.86
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 2107 0 19 0 85 1 0 0 23 0 1 0 877526310 9015296 1841 1283457024 134512640 136223643 4294415824 18446744073709551615 134630086 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 2201 1841 224 418 0 1781 0
Current children cumulated CPU time (s) 1.21
Current children cumulated vsize (KiB) 11408

[startup+3.10929 s]
/proc/loadavg: 1.27 0.73 0.31 2/45 4408
/proc/meminfo: memFree=380436/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=8804 CPUtime=2.46
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 2110 0 19 0 245 1 0 0 25 0 1 0 877526310 9015296 1844 1283457024 134512640 136223643 4294415824 18446744073709551615 134929407 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 2201 1844 224 418 0 1781 0
Current children cumulated CPU time (s) 2.81
Current children cumulated vsize (KiB) 11408

[startup+6.31012 s]
/proc/loadavg: 1.25 0.73 0.31 2/45 4408
/proc/meminfo: memFree=379444/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=9860 CPUtime=5.66
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 2365 0 19 0 564 2 0 0 25 0 1 0 877526310 10096640 2099 1283457024 134512640 136223643 4294415824 18446744073709551615 134650390 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 2465 2099 224 418 0 2045 0
Current children cumulated CPU time (s) 6.01
Current children cumulated vsize (KiB) 12464

[startup+12.7116 s]
/proc/loadavg: 1.23 0.74 0.31 2/45 4408
/proc/meminfo: memFree=378700/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=10652 CPUtime=12.06
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 2550 0 19 0 1204 2 0 0 25 0 1 0 877526310 10907648 2284 1283457024 134512640 136223643 4294415824 18446744073709551615 134931115 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 2663 2284 224 418 0 2243 0
Current children cumulated CPU time (s) 12.41
Current children cumulated vsize (KiB) 13256

[startup+25.5045 s]
/proc/loadavg: 1.19 0.75 0.32 2/45 4408
/proc/meminfo: memFree=377584/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=11708 CPUtime=24.83
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 2834 0 19 0 2481 2 0 0 25 0 1 0 877526310 11988992 2568 1283457024 134512640 136223643 4294415824 18446744073709551615 134931115 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 2927 2568 224 418 0 2507 0
Current children cumulated CPU time (s) 25.18
Current children cumulated vsize (KiB) 14312

[startup+51.1093 s]
/proc/loadavg: 1.11 0.77 0.34 2/45 4408
/proc/meminfo: memFree=376840/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=12632 CPUtime=50.35
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 3052 0 19 0 5033 2 0 0 25 0 1 0 877526310 12935168 2786 1283457024 134512640 136223643 4294415824 18446744073709551615 134929376 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 3158 2786 224 418 0 2738 0
Current children cumulated CPU time (s) 50.7
Current children cumulated vsize (KiB) 15236

[startup+102.309 s]
/proc/loadavg: 1.05 0.80 0.37 2/45 4408
/proc/meminfo: memFree=375724/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=13424 CPUtime=101.52
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 3273 0 19 0 10150 2 0 0 25 0 1 0 877526310 13746176 3007 1283457024 134512640 136223643 4294415824 18446744073709551615 134931064 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 3356 3007 224 418 0 2936 0
Current children cumulated CPU time (s) 101.87
Current children cumulated vsize (KiB) 16028

[startup+162.313 s]
/proc/loadavg: 1.02 0.83 0.41 2/45 4408
/proc/meminfo: memFree=374360/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=14756 CPUtime=161.47
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 3654 0 19 0 16145 2 0 0 25 0 1 0 877526310 15110144 3335 1283457024 134512640 136223643 4294415824 18446744073709551615 134931073 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 3689 3335 224 418 0 3269 0
Current children cumulated CPU time (s) 161.82
Current children cumulated vsize (KiB) 17360

[startup+222.306 s]
/proc/loadavg: 1.00 0.86 0.44 2/45 4408
/proc/meminfo: memFree=372624/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=16268 CPUtime=221.4
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 4094 0 19 0 22136 4 0 0 25 0 1 0 877526310 16658432 3718 1283457024 134512640 136223643 4294415824 18446744073709551615 134924277 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 4067 3718 224 418 0 3647 0
Current children cumulated CPU time (s) 221.75
Current children cumulated vsize (KiB) 18872

[startup+282.309 s]
/proc/loadavg: 1.00 0.89 0.47 2/45 4408
/proc/meminfo: memFree=372500/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=16664 CPUtime=281.36
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 4177 0 19 0 28132 4 0 0 25 0 1 0 877526310 17063936 3801 1283457024 134512640 136223643 4294415824 18446744073709551615 134611161 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 4166 3801 224 418 0 3746 0
Current children cumulated CPU time (s) 281.71
Current children cumulated vsize (KiB) 19268



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.611 s]
/proc/loadavg: 1.00 0.89 0.48 2/45 4408
/proc/meminfo: memFree=372252/1048576 swapFree=2084088/2097144
[pid=4394] ppid=4393 vsize=2604 CPUtime=0.35
/proc/4394/stat : 4394 (aspcud-trendy-1) S 4393 4394 4159 34819 4229 4202496 625 4960 0 38 0 0 35 0 20 0 1 0 877526309 2666496 301 1283457024 134512640 135304128 4291540720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/4394/statm: 651 301 253 194 0 37 0
[pid=4406] ppid=4394 vsize=16696 CPUtime=289.66
/proc/4406/stat : 4406 (clasp) R 4394 4394 4159 34819 4229 4202496 4238 0 19 0 28962 4 0 0 25 0 1 0 877526310 17096704 3825 1283457024 134512640 136223643 4294415824 18446744073709551615 134611128 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/4406/statm: 4174 3825 224 418 0 3754 0
Current children cumulated CPU time (s) 290.01
Current children cumulated vsize (KiB) 19300

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): 290.625
CPU time (s): 290.038
CPU user time (s): 289.982
CPU system time (s): 0.056003
CPU usage (%): 99.7981
Max. virtual memory (cumulated for all children) (KiB): 19532

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.982
system time used= 0.056003
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 11993
page faults= 57
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 385
involuntary context switches= 3773

runsolver used 0 second user time and 0 second system time

The end