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/3e4f8550-0b33-11df-942d-00163e1d94dc.cudf.debian.log.runsolver ./aspcud-trendy-1.4 /home/misc2010/data/misc4/debian//3e4f8550-0b33-11df-942d-00163e1d94dc.cudf /home/misc2010/tmp/201103031013/aspcud-trendy-1.4/3e4f8550-0b33-11df-942d-00163e1d94dc.cudf.debian.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.21 1.11 1.01 5/39 18629
/proc/meminfo: memFree=706048/1048576 swapFree=0/0
[pid=18628] ppid=18627 vsize=2584 CPUtime=0
/proc/18628/stat : 18628 (aspcud-trendy-1) S 18627 18628 29493 34817 29493 4202496 372 0 0 0 0 0 0 0 25 0 1 0 74883472 2646016 279 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/18628/statm: 646 279 234 194 0 33 0
[pid=18629] ppid=18628 vsize=2584 CPUtime=0
/proc/18629/stat : 18629 (aspcud-trendy-1) R 18628 18628 29493 34817 29493 4202560 107 0 0 0 0 0 0 0 25 0 1 0 74883472 2646016 130 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/18629/statm: 646 130 84 194 0 33 0
[pid=18630] ppid=18629 vsize=2584 CPUtime=0
/proc/18630/stat : 18630 (aspcud-trendy-1) R 18629 18628 29493 34817 29493 4202560 0 0 0 0 0 0 0 0 25 0 1 0 74883472 2646016 46 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/18630/statm: 646 46 0 194 0 33 0

[startup+0.114585 s]
/proc/loadavg: 1.21 1.11 1.01 5/39 18629
/proc/meminfo: memFree=706048/1048576 swapFree=0/0
[pid=18628] ppid=18627 vsize=2592 CPUtime=0.01
/proc/18628/stat : 18628 (aspcud-trendy-1) S 18627 18628 29493 34817 29493 4202496 615 2226 0 0 0 0 1 0 25 0 1 0 74883472 2654208 298 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18628/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.206606 s]
/proc/loadavg: 1.21 1.11 1.01 5/39 18629
/proc/meminfo: memFree=706048/1048576 swapFree=0/0
[pid=18628] ppid=18627 vsize=2592 CPUtime=0.01
/proc/18628/stat : 18628 (aspcud-trendy-1) S 18627 18628 29493 34817 29493 4202496 615 2226 0 0 0 0 1 0 25 0 1 0 74883472 2654208 298 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18628/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.306599 s]
/proc/loadavg: 1.21 1.11 1.01 5/39 18629
/proc/meminfo: memFree=706048/1048576 swapFree=0/0
[pid=18628] ppid=18627 vsize=2592 CPUtime=0.01
/proc/18628/stat : 18628 (aspcud-trendy-1) S 18627 18628 29493 34817 29493 4202496 615 2226 0 0 0 0 1 0 25 0 1 0 74883472 2654208 298 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18628/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.706642 s]
/proc/loadavg: 1.21 1.11 1.01 5/39 18629
/proc/meminfo: memFree=706048/1048576 swapFree=0/0
[pid=18628] ppid=18627 vsize=2592 CPUtime=0.01
/proc/18628/stat : 18628 (aspcud-trendy-1) S 18627 18628 29493 34817 29493 4202496 615 2226 0 0 0 0 1 0 25 0 1 0 74883472 2654208 298 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18628/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.51569 s]
/proc/loadavg: 1.21 1.11 1.01 2/42 18642
/proc/meminfo: memFree=649696/1048576 swapFree=0/0
[pid=18628] ppid=18627 vsize=2592 CPUtime=0.01
/proc/18628/stat : 18628 (aspcud-trendy-1) S 18627 18628 29493 34817 29493 4202496 615 2226 0 0 0 0 1 0 25 0 1 0 74883472 2654208 298 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18628/statm: 648 298 251 194 0 35 0
[pid=18640] ppid=18628 vsize=4588 CPUtime=0.01
/proc/18640/stat : 18640 (clasp) S 18628 18628 29493 34817 29493 4202496 973 0 0 0 0 1 0 0 18 0 1 0 74883473 4698112 841 1283457024 134512640 136241547 4288660448 18446744073709551615 135683070 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/18640/statm: 1147 841 175 423 0 722 0
[pid=18641] ppid=18628 vsize=6232 CPUtime=0.12
/proc/18641/stat : 18641 (gringo) R 18628 18628 29493 34817 29493 4202496 1435 0 0 0 12 0 0 0 18 0 1 0 74883473 6381568 1028 1283457024 134512640 136959103 4289367312 18446744073709551615 134618773 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/18641/statm: 1558 1028 247 598 0 957 0
[pid=18642] ppid=18628 vsize=40908 CPUtime=1.21
/proc/18642/stat : 18642 (cudf2lp) R 18628 18628 29493 34817 29493 4202496 13184 0 0 0 113 8 0 0 25 0 1 0 74883473 41889792 9957 1283457024 134512640 135749763 4292796528 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/18642/statm: 10227 9957 128 303 0 9922 0
Current children cumulated CPU time (s) 1.35
Current children cumulated vsize (KiB) 54320

[startup+3.10604 s]
/proc/loadavg: 1.27 1.13 1.02 3/41 18642
/proc/meminfo: memFree=655292/1048576 swapFree=0/0
[pid=18628] ppid=18627 vsize=2592 CPUtime=2.52
/proc/18628/stat : 18628 (aspcud-trendy-1) S 18627 18628 29493 34817 29493 4202496 615 26447 0 0 0 0 236 16 15 0 1 0 74883472 2654208 298 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18628/statm: 648 298 251 194 0 35 0
[pid=18640] ppid=18628 vsize=35404 CPUtime=0.42
/proc/18640/stat : 18640 (clasp) R 18628 18628 29493 34817 29493 4202496 9829 0 0 0 39 3 0 0 18 0 1 0 74883473 36253696 8045 1283457024 134512640 136241547 4288660448 18446744073709551615 134886659 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/18640/statm: 8851 8045 213 423 0 8426 0
Current children cumulated CPU time (s) 2.94
Current children cumulated vsize (KiB) 37996

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

[startup+3.20604 s]
/proc/loadavg: 1.27 1.13 1.02 3/41 18642
/proc/meminfo: memFree=655292/1048576 swapFree=0/0
[pid=18628] ppid=18627 vsize=2592 CPUtime=2.52
/proc/18628/stat : 18628 (aspcud-trendy-1) S 18627 18628 29493 34817 29493 4202496 615 26447 0 0 0 0 236 16 15 0 1 0 74883472 2654208 298 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18628/statm: 648 298 251 194 0 35 0
[pid=18640] ppid=18628 vsize=35404 CPUtime=0.52
/proc/18640/stat : 18640 (clasp) R 18628 18628 29493 34817 29493 4202496 9829 0 0 0 49 3 0 0 18 0 1 0 74883473 36253696 8045 1283457024 134512640 136241547 4288660448 18446744073709551615 134888875 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/18640/statm: 8851 8045 213 423 0 8426 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 37996

[startup+3.60609 s]
/proc/loadavg: 1.27 1.13 1.02 2/40 18642
/proc/meminfo: memFree=651588/1048576 swapFree=0/0
[pid=18628] ppid=18627 vsize=2592 CPUtime=2.52
/proc/18628/stat : 18628 (aspcud-trendy-1) S 18627 18628 29493 34817 29493 4202496 615 26447 0 0 0 0 236 16 15 0 1 0 74883472 2654208 298 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18628/statm: 648 298 251 194 0 35 0
[pid=18640] ppid=18628 vsize=35404 CPUtime=0.92
/proc/18640/stat : 18640 (clasp) R 18628 18628 29493 34817 29493 4202496 9829 0 0 0 89 3 0 0 18 0 1 0 74883473 36253696 8045 1283457024 134512640 136241547 4288660448 18446744073709551615 134897912 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/18640/statm: 8851 8045 213 423 0 8426 0
Current children cumulated CPU time (s) 3.44
Current children cumulated vsize (KiB) 37996

[startup+4.00618 s]
/proc/loadavg: 1.27 1.13 1.02 2/40 18642
/proc/meminfo: memFree=651588/1048576 swapFree=0/0
[pid=18628] ppid=18627 vsize=2592 CPUtime=2.52
/proc/18628/stat : 18628 (aspcud-trendy-1) S 18627 18628 29493 34817 29493 4202496 615 26447 0 0 0 0 236 16 15 0 1 0 74883472 2654208 298 1283457024 134512640 135304128 4289094752 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18628/statm: 648 298 251 194 0 35 0
[pid=18640] ppid=18628 vsize=34860 CPUtime=1.32
/proc/18640/stat : 18640 (clasp) R 18628 18628 29493 34817 29493 4202496 9860 0 0 0 129 3 0 0 19 0 1 0 74883473 35696640 7950 1283457024 134512640 136241547 4288660448 18446744073709551615 134664967 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/18640/statm: 8715 7950 227 423 0 8290 0
Current children cumulated CPU time (s) 3.84
Current children cumulated vsize (KiB) 37452

Child status: 0
Real time (s): 4.09078
CPU time (s): 3.94025
CPU user time (s): 3.72423
CPU system time (s): 0.216013
CPU usage (%): 96.3201
Max. virtual memory (cumulated for all children) (KiB): 69580

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.72423
system time used= 0.216013
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 40457
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= 1471
involuntary context switches= 996

runsolver used 0.008 second user time and 0 second system time

The end