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/201103031013/aspcud-trendy-1.4/4077.cudf.caixa.log.runsolver ./aspcud-trendy-1.4 /home/misc2010/data/misc4/caixa//4077.cudf /home/misc2010/tmp/201103031013/aspcud-trendy-1.4/4077.cudf.caixa.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.40 1.56 1.61 3/34 7149
/proc/meminfo: memFree=309200/1048576 swapFree=0/0
[pid=7148] ppid=7147 vsize=2580 CPUtime=0
/proc/7148/stat : 7148 (aspcud-trendy-1) R 7147 7148 29493 34817 29493 4202496 365 0 0 0 0 0 0 0 25 0 1 0 76193917 2641920 278 1283457024 134512640 135304128 4289236160 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/7148/statm: 645 278 234 194 0 32 0
[pid=7149] ppid=7148 vsize=2580 CPUtime=0
/proc/7149/stat : 7149 (aspcud-trendy-1) R 7148 7148 29493 34817 29493 4202560 0 0 0 0 0 0 0 0 25 0 1 0 76193917 2641920 44 1283457024 134512640 135304128 4289236160 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/7149/statm: 645 44 0 194 0 32 0

[startup+0.156575 s]
/proc/loadavg: 1.40 1.56 1.61 3/34 7149
/proc/meminfo: memFree=309200/1048576 swapFree=0/0
[pid=7148] ppid=7147 vsize=2588 CPUtime=0.01
/proc/7148/stat : 7148 (aspcud-trendy-1) S 7147 7148 29493 34817 29493 4202496 613 2231 0 0 0 0 1 0 25 0 1 0 76193917 2650112 297 1283457024 134512640 135304128 4289236160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7148/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.204616 s]
/proc/loadavg: 1.40 1.56 1.61 3/34 7149
/proc/meminfo: memFree=309200/1048576 swapFree=0/0
[pid=7148] ppid=7147 vsize=2588 CPUtime=0.01
/proc/7148/stat : 7148 (aspcud-trendy-1) S 7147 7148 29493 34817 29493 4202496 613 2231 0 0 0 0 1 0 25 0 1 0 76193917 2650112 297 1283457024 134512640 135304128 4289236160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7148/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.304601 s]
/proc/loadavg: 1.40 1.56 1.61 3/34 7149
/proc/meminfo: memFree=309200/1048576 swapFree=0/0
[pid=7148] ppid=7147 vsize=2588 CPUtime=0.01
/proc/7148/stat : 7148 (aspcud-trendy-1) S 7147 7148 29493 34817 29493 4202496 613 2231 0 0 0 0 1 0 25 0 1 0 76193917 2650112 297 1283457024 134512640 135304128 4289236160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7148/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.706349 s]
/proc/loadavg: 1.40 1.56 1.61 3/34 7149
/proc/meminfo: memFree=309200/1048576 swapFree=0/0
[pid=7148] ppid=7147 vsize=2588 CPUtime=0.01
/proc/7148/stat : 7148 (aspcud-trendy-1) S 7147 7148 29493 34817 29493 4202496 613 2231 0 0 0 0 1 0 25 0 1 0 76193917 2650112 297 1283457024 134512640 135304128 4289236160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7148/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+1.5065 s]
/proc/loadavg: 1.40 1.56 1.61 3/36 7162
/proc/meminfo: memFree=276084/1048576 swapFree=0/0
[pid=7148] ppid=7147 vsize=2588 CPUtime=0.95
/proc/7148/stat : 7148 (aspcud-trendy-1) S 7147 7148 29493 34817 29493 4202496 614 13507 0 0 0 0 87 8 16 0 1 0 76193917 2650112 297 1283457024 134512640 135304128 4289236160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7148/statm: 647 297 251 194 0 34 0
[pid=7160] ppid=7148 vsize=14400 CPUtime=0.48
/proc/7160/stat : 7160 (clasp) R 7148 7148 29493 34817 29493 4202496 3999 0 0 0 46 2 0 0 18 0 1 0 76193918 14745600 3249 1283457024 134512640 136241547 4288627680 18446744073709551615 134889405 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7160/statm: 3600 3249 213 423 0 3175 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 16988

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

[startup+1.60651 s]
/proc/loadavg: 1.40 1.56 1.61 3/36 7162
/proc/meminfo: memFree=276084/1048576 swapFree=0/0
[pid=7148] ppid=7147 vsize=2588 CPUtime=0.95
/proc/7148/stat : 7148 (aspcud-trendy-1) S 7147 7148 29493 34817 29493 4202496 614 13507 0 0 0 0 87 8 16 0 1 0 76193917 2650112 297 1283457024 134512640 135304128 4289236160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7148/statm: 647 297 251 194 0 34 0
[pid=7160] ppid=7148 vsize=14400 CPUtime=0.58
/proc/7160/stat : 7160 (clasp) R 7148 7148 29493 34817 29493 4202496 3999 0 0 0 56 2 0 0 18 0 1 0 76193918 14745600 3249 1283457024 134512640 136241547 4288627680 18446744073709551615 134889384 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7160/statm: 3600 3249 213 423 0 3175 0
Current children cumulated CPU time (s) 1.53
Current children cumulated vsize (KiB) 16988

[startup+2.00658 s]
/proc/loadavg: 1.40 1.56 1.61 3/36 7162
/proc/meminfo: memFree=276084/1048576 swapFree=0/0
[pid=7148] ppid=7147 vsize=2588 CPUtime=0.95
/proc/7148/stat : 7148 (aspcud-trendy-1) S 7147 7148 29493 34817 29493 4202496 614 13507 0 0 0 0 87 8 16 0 1 0 76193917 2650112 297 1283457024 134512640 135304128 4289236160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7148/statm: 647 297 251 194 0 34 0
[pid=7160] ppid=7148 vsize=14400 CPUtime=0.98
/proc/7160/stat : 7160 (clasp) R 7148 7148 29493 34817 29493 4202496 3999 0 0 0 96 2 0 0 19 0 1 0 76193918 14745600 3249 1283457024 134512640 136241547 4288627680 18446744073709551615 134889157 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7160/statm: 3600 3249 213 423 0 3175 0
Current children cumulated CPU time (s) 1.93
Current children cumulated vsize (KiB) 16988

[startup+2.40667 s]
/proc/loadavg: 1.40 1.56 1.61 2/35 7162
/proc/meminfo: memFree=288376/1048576 swapFree=0/0
[pid=7148] ppid=7147 vsize=2588 CPUtime=0.95
/proc/7148/stat : 7148 (aspcud-trendy-1) S 7147 7148 29493 34817 29493 4202496 614 13507 0 0 0 0 87 8 16 0 1 0 76193917 2650112 297 1283457024 134512640 135304128 4289236160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/7148/statm: 647 297 251 194 0 34 0
[pid=7160] ppid=7148 vsize=14400 CPUtime=1.38
/proc/7160/stat : 7160 (clasp) R 7148 7148 29493 34817 29493 4202496 4015 0 0 0 136 2 0 0 19 0 1 0 76193918 14745600 3265 1283457024 134512640 136241547 4288627680 18446744073709551615 134729595 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/7160/statm: 3600 3265 227 423 0 3175 0
Current children cumulated CPU time (s) 2.33
Current children cumulated vsize (KiB) 16988

Child status: 0
Real time (s): 2.47067
CPU time (s): 2.35615
CPU user time (s): 2.24014
CPU system time (s): 0.116007
CPU usage (%): 95.3647
Max. virtual memory (cumulated for all children) (KiB): 34516

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 2.24014
system time used= 0.116007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 21874
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= 947
involuntary context switches= 920

runsolver used 0 second user time and 0 second system time

The end