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/201108241238/aspcud-trendy-1.5/rand125.cudf.s-e.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e/rand125.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand125.cudf.s-e.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.00 1.00 0.93 5/35 2823
/proc/meminfo: memFree=722028/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2588 CPUtime=0
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 873188 2650112 280 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/2821/statm: 647 280 234 194 0 34 0
[pid=2822] ppid=2821 vsize=2588 CPUtime=0
/proc/2822/stat : 2822 (aspcud-trendy-1) R 2821 2821 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 873188 2650112 133 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/2822/statm: 647 133 86 194 0 34 0
[pid=2823] ppid=2822 vsize=2588 CPUtime=0
/proc/2823/stat : 2823 (aspcud-trendy-1) R 2822 2821 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 873188 2650112 47 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/2823/statm: 647 47 0 194 0 34 0

[startup+0.135686 s]
/proc/loadavg: 1.00 1.00 0.93 5/35 2823
/proc/meminfo: memFree=722028/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=0
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.205696 s]
/proc/loadavg: 1.00 1.00 0.93 5/35 2823
/proc/meminfo: memFree=722028/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=0
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.305716 s]
/proc/loadavg: 1.00 1.00 0.93 5/35 2823
/proc/meminfo: memFree=722028/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=0
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.706086 s]
/proc/loadavg: 1.00 1.00 0.93 5/35 2823
/proc/meminfo: memFree=722028/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=0
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.5059 s]
/proc/loadavg: 1.00 1.00 0.93 3/36 2835
/proc/meminfo: memFree=706012/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=1.39
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 624 15387 0 0 0 0 130 9 15 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
[pid=2833] ppid=2821 vsize=17200 CPUtime=0.1
/proc/2833/stat : 2833 (clasp) R 2821 2821 1511 34817 1511 4202496 4503 0 0 0 8 2 0 0 18 0 1 0 873189 17612800 3984 1283457024 134512640 136285277 4291870448 18446744073709551615 135058487 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2833/statm: 4300 3984 187 433 0 3865 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 19796

[startup+3.10609 s]
/proc/loadavg: 1.00 1.00 0.93 2/35 2835
/proc/meminfo: memFree=703052/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=1.39
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 624 15387 0 0 0 0 130 9 15 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
[pid=2833] ppid=2821 vsize=22560 CPUtime=1.7
/proc/2833/stat : 2833 (clasp) R 2821 2821 1511 34817 1511 4202496 6313 0 0 0 167 3 0 0 20 0 1 0 873189 23101440 5428 1283457024 134512640 136285277 4291870448 18446744073709551615 134723327 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2833/statm: 5640 5428 234 433 0 5205 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 25156

[startup+6.30676 s]
/proc/loadavg: 1.00 1.00 0.93 2/35 2835
/proc/meminfo: memFree=695992/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=1.39
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 624 15387 0 0 0 0 130 9 15 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
[pid=2833] ppid=2821 vsize=27976 CPUtime=4.9
/proc/2833/stat : 2833 (clasp) R 2821 2821 1511 34817 1511 4202496 7660 0 0 0 487 3 0 0 25 0 1 0 873189 28647424 6775 1283457024 134512640 136285277 4291870448 18446744073709551615 134733768 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2833/statm: 6994 6775 234 433 0 6559 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 30572

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

[startup+6.40676 s]
/proc/loadavg: 1.00 1.00 0.93 2/35 2835
/proc/meminfo: memFree=695992/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=1.39
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 624 15387 0 0 0 0 130 9 15 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
[pid=2833] ppid=2821 vsize=27976 CPUtime=5
/proc/2833/stat : 2833 (clasp) R 2821 2821 1511 34817 1511 4202496 7660 0 0 0 497 3 0 0 25 0 1 0 873189 28647424 6775 1283457024 134512640 136285277 4291870448 18446744073709551615 134735675 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2833/statm: 6994 6775 234 433 0 6559 0
Current children cumulated CPU time (s) 6.39
Current children cumulated vsize (KiB) 30572

[startup+9.60746 s]
/proc/loadavg: 1.00 1.00 0.93 2/35 2835
/proc/meminfo: memFree=691908/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=1.39
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 624 15387 0 0 0 0 130 9 15 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
[pid=2833] ppid=2821 vsize=35632 CPUtime=8.2
/proc/2833/stat : 2833 (clasp) R 2821 2821 1511 34817 1511 4202496 9569 0 0 0 817 3 0 0 25 0 1 0 873189 36487168 8684 1283457024 134512640 136285277 4291870448 18446744073709551615 134930669 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2833/statm: 8908 8684 234 433 0 8473 0
Current children cumulated CPU time (s) 9.59
Current children cumulated vsize (KiB) 38228

[startup+11.2078 s]
/proc/loadavg: 1.00 1.00 0.93 2/35 2835
/proc/meminfo: memFree=687196/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=1.39
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 624 15387 0 0 0 0 130 9 15 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
[pid=2833] ppid=2821 vsize=36556 CPUtime=9.8
/proc/2833/stat : 2833 (clasp) R 2821 2821 1511 34817 1511 4202496 9810 0 0 0 977 3 0 0 25 0 1 0 873189 37433344 8925 1283457024 134512640 136285277 4291870448 18446744073709551615 134955205 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2833/statm: 9139 8925 234 433 0 8704 0
Current children cumulated CPU time (s) 11.19
Current children cumulated vsize (KiB) 39152

[startup+12.008 s]
/proc/loadavg: 1.00 1.00 0.93 2/35 2835
/proc/meminfo: memFree=687196/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=1.39
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 624 15387 0 0 0 0 130 9 15 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
[pid=2833] ppid=2821 vsize=39724 CPUtime=10.6
/proc/2833/stat : 2833 (clasp) R 2821 2821 1511 34817 1511 4202496 10586 0 0 0 1056 4 0 0 25 0 1 0 873189 40677376 9701 1283457024 134512640 136285277 4291870448 18446744073709551615 134966690 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2833/statm: 9931 9701 234 433 0 9496 0
Current children cumulated CPU time (s) 11.99
Current children cumulated vsize (KiB) 42320

[startup+12.4091 s]
/proc/loadavg: 1.00 1.00 0.93 2/35 2835
/proc/meminfo: memFree=683228/1048576 swapFree=0/0
[pid=2821] ppid=2820 vsize=2596 CPUtime=1.39
/proc/2821/stat : 2821 (aspcud-trendy-1) S 2820 2821 1511 34817 1511 4202496 624 15387 0 0 0 0 130 9 15 0 1 0 873188 2658304 299 1283457024 134512640 135304128 4288000912 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/2821/statm: 649 299 251 194 0 36 0
[pid=2833] ppid=2821 vsize=36768 CPUtime=11
/proc/2833/stat : 2833 (clasp) R 2821 2821 1511 34817 1511 4202496 11242 0 0 0 1095 5 0 0 25 0 1 0 873189 37650432 7964 1283457024 134512640 136285277 4291870448 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/2833/statm: 9192 7964 241 433 0 8757 0
Current children cumulated CPU time (s) 12.39
Current children cumulated vsize (KiB) 39364

Child status: 0
Real time (s): 12.4399
CPU time (s): 12.4408
CPU user time (s): 12.2608
CPU system time (s): 0.180011
CPU usage (%): 100.007
Max. virtual memory (cumulated for all children) (KiB): 44900

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.2608
system time used= 0.180011
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 30915
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= 1015
involuntary context switches= 1121

runsolver used 0 second user time and 0 second system time

The end