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/rand230.cudf.s-e-l-s-s.log.runsolver ./aspuncud-paranoid-1.3 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand230.cudf /home/misc2010/tmp/201108251442/aspuncud-paranoid-1.3/rand230.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.14 1.19 0.84 5/36 6726
/proc/meminfo: memFree=387988/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2588 CPUtime=0
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 374 0 0 0 0 0 0 0 18 0 1 0 10073354 2650112 280 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/6723/statm: 647 280 234 194 0 34 0
[pid=6724] ppid=6723 vsize=2588 CPUtime=0
/proc/6724/stat : 6724 (aspuncud-parano) S 6723 6723 4778 34817 4778 4202560 118 0 0 0 0 0 0 0 18 0 1 0 10073354 2650112 134 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/6724/statm: 647 134 87 194 0 34 0
[pid=6725] ppid=6724 vsize=2588 CPUtime=0
/proc/6725/stat : 6725 (aspuncud-parano) R 6724 6723 4778 34817 4778 4202560 127 0 0 0 0 0 0 0 25 0 1 0 10073354 2650112 151 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/6725/statm: 647 151 104 194 0 34 0
[pid=6726] ppid=6725 vsize=2588 CPUtime=0
/proc/6726/stat : 6726 (aspuncud-parano) R 6725 6723 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10073354 2650112 47 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/6726/statm: 647 47 0 194 0 34 0

[startup+0.203084 s]
/proc/loadavg: 1.14 1.19 0.84 5/36 6726
/proc/meminfo: memFree=387988/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=0.01
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 656 2940 0 0 0 0 0 1 25 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.313105 s]
/proc/loadavg: 1.14 1.19 0.84 5/36 6726
/proc/meminfo: memFree=387988/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=0.01
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 656 2940 0 0 0 0 0 1 25 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.403112 s]
/proc/loadavg: 1.14 1.19 0.84 5/36 6726
/proc/meminfo: memFree=387988/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=0.01
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 656 2940 0 0 0 0 0 1 25 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.713158 s]
/proc/loadavg: 1.14 1.19 0.84 5/36 6726
/proc/meminfo: memFree=387988/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=0.01
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 656 2940 0 0 0 0 0 1 25 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.51327 s]
/proc/loadavg: 1.14 1.19 0.84 2/37 6740
/proc/meminfo: memFree=364416/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=0.01
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 656 2940 0 0 0 0 0 1 25 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
[pid=6738] ppid=6723 vsize=3440 CPUtime=0
/proc/6738/stat : 6738 (unclasp) S 6723 6723 4778 34817 4778 4202496 406 0 0 0 0 0 0 0 25 0 1 0 10073355 3522560 271 1283457024 134512640 135121179 4289088720 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/6738/statm: 860 271 240 149 0 51 0
[pid=6739] ppid=6723 vsize=2696 CPUtime=0
/proc/6739/stat : 6739 (gringo) S 6723 6723 4778 34817 4778 4202496 409 0 0 0 0 0 0 0 25 0 1 0 10073355 2760704 281 1283457024 134512640 137056543 4288177008 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/6739/statm: 674 281 252 622 0 49 0
[pid=6740] ppid=6723 vsize=40660 CPUtime=1.49
/proc/6740/stat : 6740 (cudf2lp) R 6723 6723 4778 34817 4778 4202496 11708 0 0 0 141 8 0 0 25 0 1 0 10073355 41635840 8804 1283457024 134512640 135786343 4294758976 18446744073709551615 134625318 0 0 6 0 0 0 0 17 0 0 0 0
/proc/6740/statm: 10165 8804 126 311 0 9852 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 49388

[startup+3.11359 s]
/proc/loadavg: 1.14 1.19 0.84 2/37 6740
/proc/meminfo: memFree=329324/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=2.19
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 656 19137 0 0 0 0 207 12 18 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
[pid=6738] ppid=6723 vsize=20936 CPUtime=0.12
/proc/6738/stat : 6738 (unclasp) R 6723 6723 4778 34817 4778 4202496 5242 0 0 0 12 0 0 0 18 0 1 0 10073355 21438464 4585 1283457024 134512640 135121179 4289088720 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6738/statm: 5234 4585 279 149 0 4425 0
[pid=6739] ppid=6723 vsize=15128 CPUtime=0.77
/proc/6739/stat : 6739 (gringo) R 6723 6723 4778 34817 4778 4202496 8058 0 0 0 69 8 0 0 18 0 1 0 10073355 15491072 3336 1283457024 134512640 137056543 4288177008 18446744073709551615 136285024 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6739/statm: 3782 3336 269 622 0 3157 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 38656

[startup+6.30435 s]
/proc/loadavg: 1.21 1.20 0.85 2/35 6740
/proc/meminfo: memFree=363208/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=2.98
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 656 27197 0 0 0 0 277 21 16 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
[pid=6738] ppid=6723 vsize=29124 CPUtime=3.31
/proc/6738/stat : 6738 (unclasp) R 6723 6723 4778 34817 4778 4202496 29004 0 0 0 323 8 0 0 25 0 1 0 10073355 29822976 6350 1283457024 134512640 135121179 4289088720 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6738/statm: 7281 6350 333 149 0 6472 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 31716

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

[startup+6.50438 s]
/proc/loadavg: 1.21 1.20 0.85 2/35 6740
/proc/meminfo: memFree=363208/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=2.98
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 656 27197 0 0 0 0 277 21 16 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
[pid=6738] ppid=6723 vsize=28992 CPUtime=3.51
/proc/6738/stat : 6738 (unclasp) R 6723 6723 4778 34817 4778 4202496 29679 0 0 0 343 8 0 0 25 0 1 0 10073355 29687808 6372 1283457024 134512640 135121179 4289088720 18446744073709551615 134734464 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6738/statm: 7248 6372 333 149 0 6439 0
Current children cumulated CPU time (s) 6.49
Current children cumulated vsize (KiB) 31584

[startup+7.30483 s]
/proc/loadavg: 1.21 1.20 0.85 2/35 6740
/proc/meminfo: memFree=363828/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=2.98
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 656 27197 0 0 0 0 277 21 16 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
[pid=6738] ppid=6723 vsize=29128 CPUtime=4.31
/proc/6738/stat : 6738 (unclasp) R 6723 6723 4778 34817 4778 4202496 35858 0 0 0 420 11 0 0 25 0 1 0 10073355 29827072 6342 1283457024 134512640 135121179 4289088720 18446744073709551615 134891399 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6738/statm: 7282 6342 333 149 0 6473 0
Current children cumulated CPU time (s) 7.29
Current children cumulated vsize (KiB) 31720

[startup+7.70511 s]
/proc/loadavg: 1.21 1.20 0.85 2/35 6740
/proc/meminfo: memFree=363828/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=2.98
/proc/6723/stat : 6723 (aspuncud-parano) S 6722 6723 4778 34817 4778 4202496 656 27197 0 0 0 0 277 21 16 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
[pid=6738] ppid=6723 vsize=29980 CPUtime=4.7
/proc/6738/stat : 6738 (unclasp) R 6723 6723 4778 34817 4778 4202496 37824 0 0 0 458 12 0 0 25 0 1 0 10073355 30699520 6556 1283457024 134512640 135121179 4289088720 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/6738/statm: 7495 6556 333 149 0 6686 0
Current children cumulated CPU time (s) 7.68
Current children cumulated vsize (KiB) 32572

[startup+7.80515 s]
/proc/loadavg: 1.19 1.20 0.85 3/37 6743
/proc/meminfo: memFree=387496/1048576 swapFree=0/0
[pid=6723] ppid=6722 vsize=2592 CPUtime=7.78
/proc/6723/stat : 6723 (aspuncud-parano) R 6722 6723 4778 34817 4778 4202496 695 65356 0 0 0 0 744 34 19 0 1 0 10073354 2654208 298 1283457024 134512640 135304128 4293681360 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/6723/statm: 648 298 251 194 0 35 0
[pid=6741] ppid=6723 vsize=0 CPUtime=0
/proc/6741/stat : 6741 (grep) Z 6723 6723 4778 34817 4778 4202508 297 0 0 0 0 0 0 0 15 0 1 0 10074134 0 0 1283457024 0 0 0 0 0 0 0 16898 0 18446744071564254338 0 0 17 0 0 0 0
/proc/6741/statm: 0 0 0 0 0 0 0
[pid=6742] ppid=6723 vsize=0 CPUtime=0
/proc/6742/stat : 6742 (tail) Z 6723 6723 4778 34817 4778 4202508 238 0 0 0 0 0 0 0 19 0 1 0 10074134 0 0 1283457024 0 0 0 0 0 0 0 16898 0 18446744071564254338 0 0 17 0 0 0 0
/proc/6742/statm: 0 0 0 0 0 0 0
[pid=6743] ppid=6723 vsize=1932 CPUtime=0.01
/proc/6743/stat : 6743 (sed) R 6723 6723 4778 34817 4778 4202496 324 0 0 0 1 0 0 0 19 0 1 0 10074134 1978368 197 1283457024 134512640 134563280 4291141248 18446744073709551615 134532787 0 0 16898 0 0 0 0 17 0 0 0 0
/proc/6743/statm: 483 197 143 13 0 86 0
Current children cumulated CPU time (s) 7.79
Current children cumulated vsize (KiB) 4524

Child status: 0
Real time (s): 7.81447
CPU time (s): 7.80049
CPU user time (s): 7.45246
CPU system time (s): 0.348021
CPU usage (%): 99.8211
Max. virtual memory (cumulated for all children) (KiB): 79492

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.45247
system time used= 0.348021
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 68480
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= 1276
involuntary context switches= 974

runsolver used 0 second user time and 0.008 second system time

The end