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/rand528.cudf.s-e.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e/rand528.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand528.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.10 1.04 1.01 5/37 17725
/proc/meminfo: memFree=674348/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2588 CPUtime=0
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 4066286 2650112 279 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/17723/statm: 647 279 234 194 0 34 0
[pid=17724] ppid=17723 vsize=2588 CPUtime=0
/proc/17724/stat : 17724 (aspcud-trendy-1) R 17723 17723 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 4066286 2650112 132 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/17724/statm: 647 132 86 194 0 34 0
[pid=17725] ppid=17724 vsize=2588 CPUtime=0
/proc/17725/stat : 17725 (aspcud-trendy-1) R 17724 17723 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4066287 2650112 46 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/17725/statm: 647 46 0 194 0 34 0

[startup+0.145219 s]
/proc/loadavg: 1.10 1.04 1.01 5/37 17725
/proc/meminfo: memFree=674348/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=0.01
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 617 2234 0 0 1 0 0 0 25 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.205228 s]
/proc/loadavg: 1.10 1.04 1.01 5/37 17725
/proc/meminfo: memFree=674348/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=0.01
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 617 2234 0 0 1 0 0 0 25 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.305242 s]
/proc/loadavg: 1.10 1.04 1.01 5/37 17725
/proc/meminfo: memFree=674348/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=0.01
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 617 2234 0 0 1 0 0 0 25 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.705376 s]
/proc/loadavg: 1.10 1.04 1.01 5/37 17725
/proc/meminfo: memFree=674348/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=0.01
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 617 2234 0 0 1 0 0 0 25 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.50549 s]
/proc/loadavg: 1.10 1.04 1.01 3/38 17737
/proc/meminfo: memFree=659572/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=1.38
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 618 15345 0 0 1 0 127 10 15 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
[pid=17735] ppid=17723 vsize=16972 CPUtime=0.11
/proc/17735/stat : 17735 (clasp) R 17723 17723 1511 34817 1511 4202496 4421 0 0 0 10 1 0 0 18 0 1 0 4066288 17379328 3903 1283457024 134512640 136285277 4294215984 18446744073709551615 134785473 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/17735/statm: 4243 3903 182 433 0 3808 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 19568

[startup+3.10584 s]
/proc/loadavg: 1.10 1.04 1.01 2/37 17737
/proc/meminfo: memFree=655620/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=1.38
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 618 15345 0 0 1 0 127 10 15 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
[pid=17735] ppid=17723 vsize=20048 CPUtime=1.71
/proc/17735/stat : 17735 (clasp) R 17723 17723 1511 34817 1511 4202496 5654 0 0 0 169 2 0 0 20 0 1 0 4066288 20529152 4773 1283457024 134512640 136285277 4294215984 18446744073709551615 134650664 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/17735/statm: 5012 4773 234 433 0 4577 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 22644

[startup+6.3066 s]
/proc/loadavg: 1.09 1.04 1.00 2/37 17737
/proc/meminfo: memFree=652652/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=1.38
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 618 15345 0 0 1 0 127 10 15 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
[pid=17735] ppid=17723 vsize=24836 CPUtime=4.9
/proc/17735/stat : 17735 (clasp) R 17723 17723 1511 34817 1511 4202496 6858 0 0 0 488 2 0 0 25 0 1 0 4066288 25432064 5977 1283457024 134512640 136285277 4294215984 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/17735/statm: 6209 5977 234 433 0 5774 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 27432

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

[startup+6.40663 s]
/proc/loadavg: 1.09 1.04 1.00 2/37 17737
/proc/meminfo: memFree=652652/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=1.38
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 618 15345 0 0 1 0 127 10 15 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
[pid=17735] ppid=17723 vsize=25760 CPUtime=5
/proc/17735/stat : 17735 (clasp) R 17723 17723 1511 34817 1511 4202496 7083 0 0 0 497 3 0 0 25 0 1 0 4066288 26378240 6202 1283457024 134512640 136285277 4294215984 18446744073709551615 134733711 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/17735/statm: 6440 6202 234 433 0 6005 0
Current children cumulated CPU time (s) 6.38
Current children cumulated vsize (KiB) 28356

[startup+9.6073 s]
/proc/loadavg: 1.09 1.04 1.00 2/36 17737
/proc/meminfo: memFree=643872/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=1.38
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 618 15345 0 0 1 0 127 10 15 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
[pid=17735] ppid=17723 vsize=33108 CPUtime=8.2
/proc/17735/stat : 17735 (clasp) R 17723 17723 1511 34817 1511 4202496 8910 0 0 0 815 5 0 0 25 0 1 0 4066288 33902592 8029 1283457024 134512640 136285277 4294215984 18446744073709551615 134930686 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/17735/statm: 8277 8029 234 433 0 7842 0
Current children cumulated CPU time (s) 9.58
Current children cumulated vsize (KiB) 35704

[startup+11.2076 s]
/proc/loadavg: 1.08 1.04 1.00 2/36 17737
/proc/meminfo: memFree=643128/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=1.38
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 618 15345 0 0 1 0 127 10 15 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
[pid=17735] ppid=17723 vsize=34692 CPUtime=9.8
/proc/17735/stat : 17735 (clasp) R 17723 17723 1511 34817 1511 4202496 9313 0 0 0 975 5 0 0 25 0 1 0 4066288 35524608 8432 1283457024 134512640 136285277 4294215984 18446744073709551615 134959560 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/17735/statm: 8673 8432 234 433 0 8238 0
Current children cumulated CPU time (s) 11.18
Current children cumulated vsize (KiB) 37288

[startup+12.0078 s]
/proc/loadavg: 1.08 1.04 1.00 2/36 17737
/proc/meminfo: memFree=643128/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=1.38
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 618 15345 0 0 1 0 127 10 15 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
[pid=17735] ppid=17723 vsize=35616 CPUtime=10.6
/proc/17735/stat : 17735 (clasp) R 17723 17723 1511 34817 1511 4202496 9549 0 0 0 1054 6 0 0 25 0 1 0 4066288 36470784 8668 1283457024 134512640 136285277 4294215984 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/17735/statm: 8904 8668 234 433 0 8469 0
Current children cumulated CPU time (s) 11.98
Current children cumulated vsize (KiB) 38212

[startup+12.4079 s]
/proc/loadavg: 1.08 1.04 1.00 2/36 17737
/proc/meminfo: memFree=640648/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=1.38
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 618 15345 0 0 1 0 127 10 15 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
[pid=17735] ppid=17723 vsize=35616 CPUtime=11
/proc/17735/stat : 17735 (clasp) R 17723 17723 1511 34817 1511 4202496 9549 0 0 0 1094 6 0 0 25 0 1 0 4066288 36470784 8668 1283457024 134512640 136285277 4294215984 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/17735/statm: 8904 8668 234 433 0 8469 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 38212

[startup+12.6082 s]
/proc/loadavg: 1.08 1.04 1.00 2/36 17737
/proc/meminfo: memFree=640648/1048576 swapFree=0/0
[pid=17723] ppid=17722 vsize=2596 CPUtime=1.38
/proc/17723/stat : 17723 (aspcud-trendy-1) S 17722 17723 1511 34817 1511 4202496 618 15345 0 0 1 0 127 10 15 0 1 0 4066286 2658304 298 1283457024 134512640 135304128 4291538672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/17723/statm: 649 298 251 194 0 36 0
[pid=17735] ppid=17723 vsize=17456 CPUtime=11.21
/proc/17735/stat : 17735 (clasp) R 17723 17723 1511 34817 1511 4202496 9557 0 0 0 1114 7 0 0 25 0 1 0 4066288 17874944 4165 1283457024 134512640 136285277 4294215984 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/17735/statm: 4364 4165 242 433 0 3929 0
Current children cumulated CPU time (s) 12.59
Current children cumulated vsize (KiB) 20052

Child status: 0
Real time (s): 12.6355
CPU time (s): 12.6248
CPU user time (s): 12.4328
CPU system time (s): 0.192012
CPU usage (%): 99.9151
Max. virtual memory (cumulated for all children) (KiB): 40692

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.4328
system time used= 0.192012
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 29183
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= 954
involuntary context switches= 1065

runsolver used 0 second user time and 0 second system time

The end