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/rand208.cudf.s-e-l-s.log.runsolver ./aspuncud-paranoid-1.3 /home/misc2010/data/2011/incremental/s-e-l-s/rand208.cudf /home/misc2010/tmp/201108251442/aspuncud-paranoid-1.3/rand208.cudf.s-e-l-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.00 0.91 5/36 6943
/proc/meminfo: memFree=479212/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2592 CPUtime=0
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 373 0 0 0 0 0 0 0 18 0 1 0 10191384 2654208 280 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/6940/statm: 648 280 234 194 0 35 0
[pid=6941] ppid=6940 vsize=2592 CPUtime=0
/proc/6941/stat : 6941 (aspuncud-parano) S 6940 6940 4778 34817 4778 4202560 118 0 0 0 0 0 0 0 18 0 1 0 10191384 2654208 134 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/6941/statm: 648 134 87 194 0 35 0
[pid=6942] ppid=6941 vsize=2592 CPUtime=0
/proc/6942/stat : 6942 (aspuncud-parano) R 6941 6940 4778 34817 4778 4202560 127 0 0 0 0 0 0 0 25 0 1 0 10191384 2654208 151 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/6942/statm: 648 151 104 194 0 35 0
[pid=6943] ppid=6942 vsize=2592 CPUtime=0
/proc/6943/stat : 6943 (aspuncud-parano) R 6942 6940 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10191384 2654208 47 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/6943/statm: 648 47 0 194 0 35 0

[startup+0.174775 s]
/proc/loadavg: 1.00 1.00 0.91 5/36 6943
/proc/meminfo: memFree=479212/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=0
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 2937 0 0 0 0 0 0 25 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.204773 s]
/proc/loadavg: 1.00 1.00 0.91 5/36 6943
/proc/meminfo: memFree=479212/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=0
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 2937 0 0 0 0 0 0 25 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.304781 s]
/proc/loadavg: 1.00 1.00 0.91 5/36 6943
/proc/meminfo: memFree=479212/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=0
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 2937 0 0 0 0 0 0 25 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.70484 s]
/proc/loadavg: 1.00 1.00 0.91 5/36 6943
/proc/meminfo: memFree=479212/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=0
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 2937 0 0 0 0 0 0 25 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50496 s]
/proc/loadavg: 1.00 1.00 0.91 2/37 6957
/proc/meminfo: memFree=458492/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=0
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 2937 0 0 0 0 0 0 25 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
[pid=6955] ppid=6940 vsize=3448 CPUtime=0
/proc/6955/stat : 6955 (unclasp) S 6940 6940 4778 34817 4778 4202496 408 0 0 0 0 0 0 0 25 0 1 0 10191386 3530752 272 1283457024 134512640 135121179 4290807408 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/6955/statm: 862 272 240 149 0 53 0
[pid=6956] ppid=6940 vsize=2696 CPUtime=0
/proc/6956/stat : 6956 (gringo) S 6940 6940 4778 34817 4778 4202496 410 0 0 0 0 0 0 0 25 0 1 0 10191386 2760704 281 1283457024 134512640 137056543 4289342608 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/6956/statm: 674 281 252 622 0 49 0
[pid=6957] ppid=6940 vsize=40448 CPUtime=1.48
/proc/6957/stat : 6957 (cudf2lp) R 6940 6940 4778 34817 4778 4202496 11644 0 0 0 142 6 0 0 25 0 1 0 10191386 41418752 8739 1283457024 134512640 135786343 4292761680 18446744073709551615 135052261 0 0 6 0 0 0 0 17 0 0 0 0
/proc/6957/statm: 10112 8739 131 311 0 9799 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 49188

[startup+3.1053 s]
/proc/loadavg: 1.00 1.00 0.91 3/37 6957
/proc/meminfo: memFree=423896/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=2.94
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 26727 0 0 0 0 281 13 15 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
[pid=6955] ppid=6940 vsize=22840 CPUtime=0.14
/proc/6955/stat : 6955 (unclasp) R 6940 6940 4778 34817 4778 4202496 5693 0 0 0 12 2 0 0 18 0 1 0 10191386 23388160 5035 1283457024 134512640 135121179 4290807408 18446744073709551615 134737114 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6955/statm: 5710 5035 290 149 0 4901 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 25436

[startup+6.3066 s]
/proc/loadavg: 1.00 1.00 0.91 2/35 6957
/proc/meminfo: memFree=453936/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=2.94
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 26727 0 0 0 0 281 13 15 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
[pid=6955] ppid=6940 vsize=29428 CPUtime=3.33
/proc/6955/stat : 6955 (unclasp) R 6940 6940 4778 34817 4778 4202496 20644 0 0 0 324 9 0 0 25 0 1 0 10191386 30134272 6483 1283457024 134512640 135121179 4290807408 18446744073709551615 134611141 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6955/statm: 7357 6483 328 149 0 6548 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 32024

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

[startup+6.40665 s]
/proc/loadavg: 1.00 1.00 0.91 2/35 6957
/proc/meminfo: memFree=453936/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=2.94
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 26727 0 0 0 0 281 13 15 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
[pid=6955] ppid=6940 vsize=30300 CPUtime=3.43
/proc/6955/stat : 6955 (unclasp) R 6940 6940 4778 34817 4778 4202496 21304 0 0 0 333 10 0 0 25 0 1 0 10191386 31027200 6615 1283457024 134512640 135121179 4290807408 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6955/statm: 7575 6615 328 149 0 6766 0
Current children cumulated CPU time (s) 6.37
Current children cumulated vsize (KiB) 32896

[startup+8.00726 s]
/proc/loadavg: 1.00 1.00 0.91 2/35 6957
/proc/meminfo: memFree=453812/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=2.94
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 26727 0 0 0 0 281 13 15 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
[pid=6955] ppid=6940 vsize=30304 CPUtime=5.03
/proc/6955/stat : 6955 (unclasp) R 6940 6940 4778 34817 4778 4202496 27591 0 0 0 489 14 0 0 25 0 1 0 10191386 31031296 6639 1283457024 134512640 135121179 4290807408 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6955/statm: 7576 6639 328 149 0 6767 0
Current children cumulated CPU time (s) 7.97
Current children cumulated vsize (KiB) 32900

[startup+8.80756 s]
/proc/loadavg: 1.00 1.00 0.91 2/35 6957
/proc/meminfo: memFree=453820/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=2.94
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 26727 0 0 0 0 281 13 15 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
[pid=6955] ppid=6940 vsize=30304 CPUtime=5.83
/proc/6955/stat : 6955 (unclasp) R 6940 6940 4778 34817 4778 4202496 29323 0 0 0 569 14 0 0 25 0 1 0 10191386 31031296 6638 1283457024 134512640 135121179 4290807408 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6955/statm: 7576 6638 328 149 0 6767 0
Current children cumulated CPU time (s) 8.77
Current children cumulated vsize (KiB) 32900

[startup+9.6079 s]
/proc/loadavg: 1.00 1.00 0.91 2/35 6957
/proc/meminfo: memFree=453820/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=2.94
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 26727 0 0 0 0 281 13 15 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
[pid=6955] ppid=6940 vsize=30304 CPUtime=6.63
/proc/6955/stat : 6955 (unclasp) R 6940 6940 4778 34817 4778 4202496 31253 0 0 0 647 16 0 0 25 0 1 0 10191386 31031296 6638 1283457024 134512640 135121179 4290807408 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6955/statm: 7576 6638 328 149 0 6767 0
Current children cumulated CPU time (s) 9.57
Current children cumulated vsize (KiB) 32900

[startup+9.80794 s]
/proc/loadavg: 1.00 1.00 0.91 2/35 6957
/proc/meminfo: memFree=453820/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2596 CPUtime=2.94
/proc/6940/stat : 6940 (aspuncud-parano) S 6939 6940 4778 34817 4778 4202496 662 26727 0 0 0 0 281 13 15 0 1 0 10191384 2658304 298 1283457024 134512640 135304128 4288590848 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6940/statm: 649 298 251 194 0 36 0
[pid=6955] ppid=6940 vsize=29432 CPUtime=6.83
/proc/6955/stat : 6955 (unclasp) R 6940 6940 4778 34817 4778 4202496 31717 0 0 0 666 17 0 0 25 0 1 0 10191386 30138368 6486 1283457024 134512640 135121179 4290807408 18446744073709551615 134891771 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6955/statm: 7358 6486 328 149 0 6549 0
Current children cumulated CPU time (s) 9.77
Current children cumulated vsize (KiB) 32028

[startup+9.90795 s]
/proc/loadavg: 1.00 1.00 0.91 2/35 6967
/proc/meminfo: memFree=478548/1048576 swapFree=0/0
[pid=6940] ppid=6939 vsize=2600 CPUtime=9.88
/proc/6940/stat : 6940 (aspuncud-parano) R 6939 6940 4778 34817 4778 4194304 874 60668 0 0 0 0 956 32 20 0 1 0 10191384 2662400 300 1283457024 134512640 135304128 4288590848 18446744073709551615 134776523 0 65536 16902 1132543225 0 0 0 17 0 0 0 0
/proc/6940/statm: 650 300 252 194 0 37 0
[pid=6967] ppid=6940 vsize=0 CPUtime=0
/proc/6967/stat : 6967 (rm) Z 6940 6940 4778 34817 4778 4202508 181 0 0 0 0 0 0 0 20 0 1 0 10192375 0 0 1283457024 0 0 0 0 0 0 0 16898 0 18446744071564254338 0 0 17 0 0 0 0
/proc/6967/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.88
Current children cumulated vsize (KiB) 2600

Child status: 0
Real time (s): 9.90988
CPU time (s): 9.88862
CPU user time (s): 9.5686
CPU system time (s): 0.32002
CPU usage (%): 99.7854
Max. virtual memory (cumulated for all children) (KiB): 77600

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.5686
system time used= 0.32002
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 61746
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= 1287
involuntary context switches= 998

runsolver used 0 second user time and 0.008 second system time

The end