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/rand986.sarge.cudf.sarge.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge/rand986.sarge.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand986.sarge.cudf.sarge.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.24 1.06 1.02 4/46 31157
/proc/meminfo: memFree=850104/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2588 CPUtime=0
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 884180529 2650112 282 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/31155/statm: 647 282 237 194 0 33 0
[pid=31156] ppid=31155 vsize=2588 CPUtime=0
/proc/31156/stat : 31156 (aspcud-trendy-1) R 31155 31155 4159 34819 4229 4202560 105 0 0 0 0 0 0 0 25 0 1 0 884180529 2650112 128 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/31156/statm: 647 128 82 194 0 33 0
[pid=31157] ppid=31156 vsize=2588 CPUtime=0
/proc/31157/stat : 31157 (aspcud-trendy-1) R 31156 31155 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 884180529 2650112 46 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/31157/statm: 647 46 0 194 0 33 0

[startup+0.194888 s]
/proc/loadavg: 1.24 1.06 1.02 4/46 31157
/proc/meminfo: memFree=850104/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 2220 0 0 0 0 0 0 25 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.214889 s]
/proc/loadavg: 1.24 1.06 1.02 4/46 31157
/proc/meminfo: memFree=850104/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 2220 0 0 0 0 0 0 25 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.314915 s]
/proc/loadavg: 1.24 1.06 1.02 4/46 31157
/proc/meminfo: memFree=850104/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 2220 0 0 0 0 0 0 25 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2600

[startup+0.715021 s]
/proc/loadavg: 1.24 1.06 1.02 4/46 31157
/proc/meminfo: memFree=850104/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0.53
Current children cumulated vsize (KiB) 2600

[startup+1.51521 s]
/proc/loadavg: 1.24 1.06 1.02 2/46 31169
/proc/meminfo: memFree=841324/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=10312 CPUtime=0.96
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 2778 0 0 0 96 0 0 0 23 0 1 0 884180530 10559488 2289 1283457024 134512640 136223643 4291325552 18446744073709551615 134928848 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 2578 2289 225 418 0 2158 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 12912

[startup+3.11553 s]
/proc/loadavg: 1.24 1.06 1.02 2/46 31169
/proc/meminfo: memFree=841324/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=10312 CPUtime=2.56
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 2778 0 0 0 256 0 0 0 25 0 1 0 884180530 10559488 2289 1283457024 134512640 136223643 4291325552 18446744073709551615 134910783 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 2578 2289 225 418 0 2158 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 12912

[startup+6.30616 s]
/proc/loadavg: 1.22 1.06 1.02 2/46 31169
/proc/meminfo: memFree=840084/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=12688 CPUtime=5.75
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 3361 0 0 0 574 1 0 0 25 0 1 0 884180530 12992512 2872 1283457024 134512640 136223643 4291325552 18446744073709551615 134917898 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 3172 2872 225 418 0 2752 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 15288

[startup+12.7073 s]
/proc/loadavg: 1.20 1.06 1.02 2/46 31169
/proc/meminfo: memFree=838976/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=12952 CPUtime=12.15
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 3429 0 0 0 1213 2 0 0 25 0 1 0 884180530 13262848 2940 1283457024 134512640 136223643 4291325552 18446744073709551615 134930043 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 3238 2940 225 418 0 2818 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 15552

[startup+25.5097 s]
/proc/loadavg: 1.16 1.06 1.01 2/46 31169
/proc/meminfo: memFree=838480/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=13480 CPUtime=24.94
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 3573 0 0 0 2492 2 0 0 25 0 1 0 884180530 13803520 3084 1283457024 134512640 136223643 4291325552 18446744073709551615 134928852 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 3370 3084 225 418 0 2950 0
Current children cumulated CPU time (s) 25.47
Current children cumulated vsize (KiB) 16080

[startup+51.1152 s]
/proc/loadavg: 1.10 1.05 1.01 2/46 31169
/proc/meminfo: memFree=837984/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=13876 CPUtime=50.55
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 3659 0 0 0 5053 2 0 0 25 0 1 0 884180530 14209024 3170 1283457024 134512640 136223643 4291325552 18446744073709551615 134931140 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 3469 3170 225 418 0 3049 0
Current children cumulated CPU time (s) 51.08
Current children cumulated vsize (KiB) 16476

[startup+102.306 s]
/proc/loadavg: 1.04 1.04 1.01 2/46 31169
/proc/meminfo: memFree=837364/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=14272 CPUtime=101.69
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 3789 0 0 0 10167 2 0 0 25 0 1 0 884180530 14614528 3300 1283457024 134512640 136223643 4291325552 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 3568 3300 225 418 0 3148 0
Current children cumulated CPU time (s) 102.22
Current children cumulated vsize (KiB) 16872

[startup+162.309 s]
/proc/loadavg: 1.01 1.03 1.00 2/46 31169
/proc/meminfo: memFree=837116/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=14536 CPUtime=161.62
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 3833 0 0 0 16160 2 0 0 25 0 1 0 884180530 14884864 3344 1283457024 134512640 136223643 4291325552 18446744073709551615 134712512 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 3634 3344 225 418 0 3214 0
Current children cumulated CPU time (s) 162.15
Current children cumulated vsize (KiB) 17136

[startup+222.313 s]
/proc/loadavg: 1.00 1.02 1.00 2/46 31169
/proc/meminfo: memFree=836744/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=14668 CPUtime=221.56
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 3882 0 0 0 22153 3 0 0 25 0 1 0 884180530 15020032 3393 1283457024 134512640 136223643 4291325552 18446744073709551615 134611148 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 3667 3393 225 418 0 3247 0
Current children cumulated CPU time (s) 222.09
Current children cumulated vsize (KiB) 17268

[startup+282.305 s]
/proc/loadavg: 1.00 1.02 1.00 2/46 31169
/proc/meminfo: memFree=836372/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=15064 CPUtime=281.51
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 3964 0 0 0 28148 3 0 0 25 0 1 0 884180530 15425536 3475 1283457024 134512640 136223643 4291325552 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 3766 3475 225 418 0 3346 0
Current children cumulated CPU time (s) 282.04
Current children cumulated vsize (KiB) 17664



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.306 s]
/proc/loadavg: 1.00 1.02 1.00 2/46 31169
/proc/meminfo: memFree=836372/1048576 swapFree=2077436/2097144
[pid=31155] ppid=31154 vsize=2600 CPUtime=0.53
/proc/31155/stat : 31155 (aspcud-trendy-1) S 31154 31155 4159 34819 4229 4202496 618 8634 0 0 0 0 48 5 21 0 1 0 884180529 2662400 301 1283457024 134512640 135304128 4292694016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31155/statm: 650 301 253 194 0 36 0
[pid=31167] ppid=31155 vsize=15064 CPUtime=289.52
/proc/31167/stat : 31167 (clasp) R 31155 31155 4159 34819 4229 4202496 3964 0 0 0 28949 3 0 0 25 0 1 0 884180530 15425536 3475 1283457024 134512640 136223643 4291325552 18446744073709551615 134711956 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31167/statm: 3766 3475 225 418 0 3346 0
Current children cumulated CPU time (s) 290.05
Current children cumulated vsize (KiB) 17664

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.322
CPU time (s): 290.07
CPU user time (s): 289.974
CPU system time (s): 0.096006
CPU usage (%): 99.9133
Max. virtual memory (cumulated for all children) (KiB): 17664

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.974
system time used= 0.096006
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 15816
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 547
involuntary context switches= 4171

runsolver used 0.008 second user time and 0 second system time

The end