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/201108251442/aspuncud-paranoid-1.3/rand946.cudf.s-e-l-s-s.log.runsolver ./aspuncud-paranoid-1.3 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand946.cudf /home/misc2010/tmp/201108251442/aspuncud-paranoid-1.3/rand946.cudf.s-e-l-s-s.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.02 1.00 4/34 16928
/proc/meminfo: memFree=422652/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2584 CPUtime=0
/proc/16927/stat : 16927 (aspuncud-parano) R 16926 16927 4778 34817 4778 4202496 365 0 0 0 0 0 0 0 25 0 1 0 11066970 2646016 279 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/16927/statm: 646 279 234 194 0 33 0
[pid=16928] ppid=16927 vsize=2584 CPUtime=0
/proc/16928/stat : 16928 (aspuncud-parano) R 16927 16927 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 11066970 2646016 45 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/16928/statm: 646 45 0 194 0 33 0

[startup+0.176372 s]
/proc/loadavg: 1.00 1.02 1.00 4/34 16928
/proc/meminfo: memFree=422652/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2588 CPUtime=0
/proc/16927/stat : 16927 (aspuncud-parano) S 16926 16927 4778 34817 4778 4202496 654 2939 0 0 0 0 0 0 25 0 1 0 11066970 2650112 297 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16927/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.206364 s]
/proc/loadavg: 1.00 1.02 1.00 4/34 16928
/proc/meminfo: memFree=422652/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2588 CPUtime=0
/proc/16927/stat : 16927 (aspuncud-parano) S 16926 16927 4778 34817 4778 4202496 654 2939 0 0 0 0 0 0 25 0 1 0 11066970 2650112 297 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16927/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.306385 s]
/proc/loadavg: 1.00 1.02 1.00 4/34 16928
/proc/meminfo: memFree=422652/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2588 CPUtime=0
/proc/16927/stat : 16927 (aspuncud-parano) S 16926 16927 4778 34817 4778 4202496 654 2939 0 0 0 0 0 0 25 0 1 0 11066970 2650112 297 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16927/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.706458 s]
/proc/loadavg: 1.00 1.02 1.00 4/34 16928
/proc/meminfo: memFree=422652/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2588 CPUtime=0
/proc/16927/stat : 16927 (aspuncud-parano) S 16926 16927 4778 34817 4778 4202496 654 2939 0 0 0 0 0 0 25 0 1 0 11066970 2650112 297 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16927/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+1.5066 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 16944
/proc/meminfo: memFree=401432/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2588 CPUtime=0
/proc/16927/stat : 16927 (aspuncud-parano) S 16926 16927 4778 34817 4778 4202496 654 2939 0 0 0 0 0 0 25 0 1 0 11066970 2650112 297 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16927/statm: 647 297 251 194 0 34 0
[pid=16942] ppid=16927 vsize=3444 CPUtime=0
/proc/16942/stat : 16942 (unclasp) S 16927 16927 4778 34817 4778 4202496 407 0 0 0 0 0 0 0 25 0 1 0 11066972 3526656 272 1283457024 134512640 135121179 4290332160 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16942/statm: 861 272 240 149 0 52 0
[pid=16943] ppid=16927 vsize=2692 CPUtime=0
/proc/16943/stat : 16943 (gringo) S 16927 16927 4778 34817 4778 4202496 409 0 0 0 0 0 0 0 25 0 1 0 11066972 2756608 281 1283457024 134512640 137056543 4292806624 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16943/statm: 673 281 252 622 0 48 0
[pid=16944] ppid=16927 vsize=40668 CPUtime=1.48
/proc/16944/stat : 16944 (cudf2lp) R 16927 16927 4778 34817 4778 4202496 11705 0 0 0 140 8 0 0 25 0 1 0 11066972 41644032 8801 1283457024 134512640 135786343 4288803984 18446744073709551615 135044416 0 0 6 0 0 0 0 17 0 0 0 0
/proc/16944/statm: 10167 8801 126 311 0 9854 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 49392

[startup+3.10692 s]
/proc/loadavg: 1.00 1.02 1.00 3/37 16944
/proc/meminfo: memFree=367332/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2588 CPUtime=2.16
/proc/16927/stat : 16927 (aspuncud-parano) S 16926 16927 4778 34817 4778 4202496 654 19137 0 0 0 0 204 12 18 0 1 0 11066970 2650112 297 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16927/statm: 647 297 251 194 0 34 0
[pid=16942] ppid=16927 vsize=20908 CPUtime=0.12
/proc/16942/stat : 16942 (unclasp) S 16927 16927 4778 34817 4778 4202496 5233 0 0 0 11 1 0 0 18 0 1 0 11066972 21409792 4576 1283457024 134512640 135121179 4290332160 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16942/statm: 5227 4576 279 149 0 4418 0
[pid=16943] ppid=16927 vsize=15104 CPUtime=0.81
/proc/16943/stat : 16943 (gringo) R 16927 16927 4778 34817 4778 4202496 8052 0 0 0 80 1 0 0 18 0 1 0 11066972 15466496 3340 1283457024 134512640 137056543 4292806624 18446744073709551615 136285117 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16943/statm: 3776 3340 269 622 0 3151 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 38600

[startup+6.30793 s]
/proc/loadavg: 1.08 1.04 1.01 2/35 16944
/proc/meminfo: memFree=397248/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2588 CPUtime=2.97
/proc/16927/stat : 16927 (aspuncud-parano) S 16926 16927 4778 34817 4778 4202496 654 27191 0 0 0 0 284 13 16 0 1 0 11066970 2650112 297 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16927/statm: 647 297 251 194 0 34 0
[pid=16942] ppid=16927 vsize=28500 CPUtime=3.32
/proc/16942/stat : 16942 (unclasp) R 16927 16927 4778 34817 4778 4202496 31340 0 0 0 318 14 0 0 25 0 1 0 11066972 29184000 6244 1283457024 134512640 135121179 4290332160 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16942/statm: 7125 6244 328 149 0 6316 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 31088

[startup+12.7099 s]
/proc/loadavg: 1.07 1.04 1.00 2/35 16944
/proc/meminfo: memFree=397132/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2588 CPUtime=2.97
/proc/16927/stat : 16927 (aspuncud-parano) S 16926 16927 4778 34817 4778 4202496 654 27191 0 0 0 0 284 13 16 0 1 0 11066970 2650112 297 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16927/statm: 647 297 251 194 0 34 0
[pid=16942] ppid=16927 vsize=29356 CPUtime=9.71
/proc/16942/stat : 16942 (unclasp) R 16927 16927 4778 34817 4778 4202496 83659 0 0 0 933 38 0 0 25 0 1 0 11066972 30060544 6465 1283457024 134512640 135121179 4290332160 18446744073709551615 134611817 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16942/statm: 7339 6465 328 149 0 6530 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 31944

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

[startup+12.81 s]
/proc/loadavg: 1.07 1.04 1.00 2/35 16944
/proc/meminfo: memFree=397132/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2588 CPUtime=2.97
/proc/16927/stat : 16927 (aspuncud-parano) S 16926 16927 4778 34817 4778 4202496 654 27191 0 0 0 0 284 13 16 0 1 0 11066970 2650112 297 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16927/statm: 647 297 251 194 0 34 0
[pid=16942] ppid=16927 vsize=29940 CPUtime=9.81
/proc/16942/stat : 16942 (unclasp) R 16927 16927 4778 34817 4778 4202496 84389 0 0 0 943 38 0 0 25 0 1 0 11066972 30658560 6611 1283457024 134512640 135121179 4290332160 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16942/statm: 7485 6611 328 149 0 6676 0
Current children cumulated CPU time (s) 12.78
Current children cumulated vsize (KiB) 32528

[startup+13.01 s]
/proc/loadavg: 1.07 1.04 1.00 2/35 16944
/proc/meminfo: memFree=397132/1048576 swapFree=0/0
[pid=16927] ppid=16926 vsize=2588 CPUtime=2.97
/proc/16927/stat : 16927 (aspuncud-parano) S 16926 16927 4778 34817 4778 4202496 654 27191 0 0 0 0 284 13 16 0 1 0 11066970 2650112 297 1283457024 134512640 135304128 4291755776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16927/statm: 647 297 251 194 0 34 0
[pid=16942] ppid=16927 vsize=29356 CPUtime=10.01
/proc/16942/stat : 16942 (unclasp) R 16927 16927 4778 34817 4778 4202496 85412 0 0 0 961 40 0 0 25 0 1 0 11066972 30060544 6466 1283457024 134512640 135121179 4290332160 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16942/statm: 7339 6466 328 149 0 6530 0
Current children cumulated CPU time (s) 12.98
Current children cumulated vsize (KiB) 31944

Child status: 0
Real time (s): 13.0927
CPU time (s): 13.0888
CPU user time (s): 12.5248
CPU system time (s): 0.564035
CPU usage (%): 99.9707
Max. virtual memory (cumulated for all children) (KiB): 79112

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.5248
system time used= 0.564035
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 115899
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= 1282
involuntary context switches= 1035

runsolver used 0 second user time and 0 second system time

The end