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/rand7b4167.cudf.difficult.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/difficult//rand7b4167.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand7b4167.cudf.difficult.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.41 1.15 1.04 5/46 29385
/proc/meminfo: memFree=622140/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2584 CPUtime=0
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 374 0 0 0 0 0 0 0 18 0 1 0 883641963 2646016 281 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/29383/statm: 646 281 237 194 0 32 0
[pid=29384] ppid=29383 vsize=2584 CPUtime=0
/proc/29384/stat : 29384 (aspcud-trendy-1) R 29383 29383 4159 34819 4229 4202560 105 0 0 0 0 0 0 0 25 0 1 0 883641963 2646016 127 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/29384/statm: 646 127 82 194 0 32 0
[pid=29385] ppid=29384 vsize=2584 CPUtime=0
/proc/29385/stat : 29385 (aspcud-trendy-1) R 29384 29383 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 883641963 2646016 45 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/29385/statm: 646 45 0 194 0 32 0

[startup+0.195698 s]
/proc/loadavg: 1.41 1.15 1.04 5/46 29385
/proc/meminfo: memFree=622140/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=0.01
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 2220 0 0 0 0 0 1 25 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.215693 s]
/proc/loadavg: 1.41 1.15 1.04 5/46 29385
/proc/meminfo: memFree=622140/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=0.01
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 2220 0 0 0 0 0 1 25 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.315706 s]
/proc/loadavg: 1.41 1.15 1.04 5/46 29385
/proc/meminfo: memFree=622140/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=0.01
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 2220 0 0 0 0 0 1 25 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.715777 s]
/proc/loadavg: 1.41 1.15 1.04 5/46 29385
/proc/meminfo: memFree=622140/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=0.01
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 2220 0 0 0 0 0 1 25 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.51597 s]
/proc/loadavg: 1.41 1.15 1.04 2/48 29397
/proc/meminfo: memFree=582804/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=0.91
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 11440 0 0 0 0 86 5 18 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
[pid=29395] ppid=29383 vsize=14256 CPUtime=0.07
/proc/29395/stat : 29395 (clasp) R 29383 29383 4159 34819 4229 4202496 3776 0 0 0 7 0 0 0 18 0 1 0 883641964 14598144 3257 1283457024 134512640 136223643 4288310160 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29395/statm: 3564 3257 174 418 0 3144 0
[pid=29396] ppid=29383 vsize=25728 CPUtime=0.51
/proc/29396/stat : 29396 (gringo) R 29383 29383 4159 34819 4229 4202496 6301 0 0 0 47 4 0 0 18 0 1 0 883641964 26345472 4770 1283457024 134512640 136959103 4291651392 18446744073709551615 136227602 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29396/statm: 6432 4770 256 598 0 5831 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 42580

[startup+3.10629 s]
/proc/loadavg: 1.41 1.15 1.04 2/46 29397
/proc/meminfo: memFree=601684/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=1.54
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 18459 0 0 0 0 144 10 15 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
[pid=29395] ppid=29383 vsize=22916 CPUtime=1.56
/proc/29395/stat : 29395 (clasp) R 29383 29383 4159 34819 4229 4202496 6154 0 0 0 155 1 0 0 20 0 1 0 883641964 23465984 5218 1283457024 134512640 136223643 4288310160 18446744073709551615 134611161 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29395/statm: 5729 5218 225 418 0 5309 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 25512

[startup+6.30702 s]
/proc/loadavg: 1.38 1.15 1.04 2/46 29397
/proc/meminfo: memFree=600072/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=1.54
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 18459 0 0 0 0 144 10 15 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
[pid=29395] ppid=29383 vsize=24764 CPUtime=4.76
/proc/29395/stat : 29395 (clasp) R 29383 29383 4159 34819 4229 4202496 6617 0 0 0 475 1 0 0 25 0 1 0 883641964 25358336 5681 1283457024 134512640 136223643 4288310160 18446744073709551615 134929006 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29395/statm: 6191 5681 225 418 0 5771 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 27360

Solver just ended. Dumping a history of the last processes samples

[startup+6.40705 s]
/proc/loadavg: 1.38 1.15 1.04 2/46 29397
/proc/meminfo: memFree=600072/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=1.54
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 18459 0 0 0 0 144 10 15 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
[pid=29395] ppid=29383 vsize=24764 CPUtime=4.86
/proc/29395/stat : 29395 (clasp) R 29383 29383 4159 34819 4229 4202496 6617 0 0 0 485 1 0 0 25 0 1 0 883641964 25358336 5681 1283457024 134512640 136223643 4288310160 18446744073709551615 134711897 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29395/statm: 6191 5681 225 418 0 5771 0
Current children cumulated CPU time (s) 6.4
Current children cumulated vsize (KiB) 27360

[startup+7.20724 s]
/proc/loadavg: 1.38 1.15 1.04 2/46 29397
/proc/meminfo: memFree=600072/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=1.54
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 18459 0 0 0 0 144 10 15 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
[pid=29395] ppid=29383 vsize=24896 CPUtime=5.66
/proc/29395/stat : 29395 (clasp) R 29383 29383 4159 34819 4229 4202496 6649 0 0 0 565 1 0 0 25 0 1 0 883641964 25493504 5713 1283457024 134512640 136223643 4288310160 18446744073709551615 134930859 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29395/statm: 6224 5713 225 418 0 5804 0
Current children cumulated CPU time (s) 7.2
Current children cumulated vsize (KiB) 27492

[startup+8.00745 s]
/proc/loadavg: 1.35 1.15 1.04 2/46 29397
/proc/meminfo: memFree=599948/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=1.54
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 18459 0 0 0 0 144 10 15 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
[pid=29395] ppid=29383 vsize=24896 CPUtime=6.46
/proc/29395/stat : 29395 (clasp) R 29383 29383 4159 34819 4229 4202496 6649 0 0 0 645 1 0 0 25 0 1 0 883641964 25493504 5713 1283457024 134512640 136223643 4288310160 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29395/statm: 6224 5713 225 418 0 5804 0
Current children cumulated CPU time (s) 8
Current children cumulated vsize (KiB) 27492

[startup+8.2075 s]
/proc/loadavg: 1.35 1.15 1.04 2/46 29397
/proc/meminfo: memFree=599948/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=1.54
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 18459 0 0 0 0 144 10 15 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
[pid=29395] ppid=29383 vsize=24896 CPUtime=6.66
/proc/29395/stat : 29395 (clasp) R 29383 29383 4159 34819 4229 4202496 6649 0 0 0 665 1 0 0 25 0 1 0 883641964 25493504 5713 1283457024 134512640 136223643 4288310160 18446744073709551615 134923817 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29395/statm: 6224 5713 225 418 0 5804 0
Current children cumulated CPU time (s) 8.2
Current children cumulated vsize (KiB) 27492

[startup+8.30754 s]
/proc/loadavg: 1.35 1.15 1.04 2/46 29397
/proc/meminfo: memFree=599948/1048576 swapFree=2077628/2097144
[pid=29383] ppid=29382 vsize=2596 CPUtime=1.54
/proc/29383/stat : 29383 (aspcud-trendy-1) S 29382 29383 4159 34819 4229 4202496 618 18459 0 0 0 0 144 10 15 0 1 0 883641963 2658304 300 1283457024 134512640 135304128 4290518512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/29383/statm: 649 300 253 194 0 35 0
[pid=29395] ppid=29383 vsize=24896 CPUtime=6.76
/proc/29395/stat : 29395 (clasp) R 29383 29383 4159 34819 4229 4202496 6649 0 0 0 675 1 0 0 25 0 1 0 883641964 25493504 5713 1283457024 134512640 136223643 4288310160 18446744073709551615 134931129 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/29395/statm: 6224 5713 225 418 0 5804 0
Current children cumulated CPU time (s) 8.3
Current children cumulated vsize (KiB) 27492

Child status: 0
Real time (s): 8.38601
CPU time (s): 8.38452
CPU user time (s): 8.26052
CPU system time (s): 0.124007
CPU usage (%): 99.9823
Max. virtual memory (cumulated for all children) (KiB): 48392

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 8.26052
system time used= 0.124007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 29337
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= 716
involuntary context switches= 575

runsolver used 0 second user time and 0 second system time

The end