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/packup2mp4tr-0.6/33bb2fbc-9512-11e0-9181-00163e1e087d.cudf.dudf-real.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/dudf-real//33bb2fbc-9512-11e0-9181-00163e1e087d.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/33bb2fbc-9512-11e0-9181-00163e1e087d.cudf.dudf-real.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.13 1.05 4/34 18682
/proc/meminfo: memFree=589572/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=3848 CPUtime=0.01
/proc/18682/stat : 18682 (packup) R 18681 18681 1511 34817 1511 4202496 451 0 0 0 0 1 0 0 25 0 1 0 4131989 3940352 380 1283457024 134512640 134752139 4292513648 18446744073709551615 4157244131 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/18682/statm: 962 380 286 59 0 126 0

[startup+0.117366 s]
/proc/loadavg: 1.10 1.13 1.05 4/34 18682
/proc/meminfo: memFree=589572/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=8044 CPUtime=0.11
/proc/18682/stat : 18682 (packup) R 18681 18681 1511 34817 1511 4202496 1502 0 0 0 10 1 0 0 25 0 1 0 4131989 8237056 1431 1283457024 134512640 134752139 4292513648 18446744073709551615 134683175 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/18682/statm: 2011 1431 286 59 0 1175 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 10616

[startup+0.20747 s]
/proc/loadavg: 1.10 1.13 1.05 4/34 18682
/proc/meminfo: memFree=589572/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=10980 CPUtime=0.21
/proc/18682/stat : 18682 (packup) R 18681 18681 1511 34817 1511 4202496 2242 0 0 0 19 2 0 0 25 0 1 0 4131989 11243520 2171 1283457024 134512640 134752139 4292513648 18446744073709551615 134681798 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/18682/statm: 2745 2171 286 59 0 1909 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 13552

[startup+0.307491 s]
/proc/loadavg: 1.10 1.13 1.05 4/34 18682
/proc/meminfo: memFree=589572/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=14040 CPUtime=0.31
/proc/18682/stat : 18682 (packup) R 18681 18681 1511 34817 1511 4202496 3007 0 0 0 29 2 0 0 25 0 1 0 4131989 14376960 2936 1283457024 134512640 134752139 4292513648 18446744073709551615 4157221336 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/18682/statm: 3510 2936 286 59 0 2674 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 16612

[startup+0.707577 s]
/proc/loadavg: 1.10 1.13 1.05 4/34 18682
/proc/meminfo: memFree=589572/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=24796 CPUtime=0.71
/proc/18682/stat : 18682 (packup) R 18681 18681 1511 34817 1511 4202496 5699 0 0 0 69 2 0 0 25 0 1 0 4131989 25391104 5628 1283457024 134512640 134752139 4292513648 18446744073709551615 134682058 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/18682/statm: 6199 5628 286 59 0 5363 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 27368

[startup+1.50775 s]
/proc/loadavg: 1.10 1.13 1.05 2/35 18683
/proc/meminfo: memFree=553444/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=39812 CPUtime=1.26
/proc/18682/stat : 18682 (packup) S 18681 18681 1511 34817 1511 4202496 9492 0 0 0 118 8 0 0 25 0 1 0 4131989 40767488 9300 1283457024 134512640 134752139 4292513648 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/18682/statm: 9953 9300 325 59 0 9117 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 42384

[startup+3.10816 s]
/proc/loadavg: 1.10 1.13 1.05 2/37 18685
/proc/meminfo: memFree=529108/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=39816 CPUtime=2.52
/proc/18682/stat : 18682 (packup) S 18681 18681 1511 34817 1511 4202496 9567 8818 0 0 126 19 91 16 18 0 1 0 4131989 40771584 9324 1283457024 134512640 134752139 4292513648 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/18682/statm: 9954 9324 333 59 0 9118 0
Current children cumulated CPU time (s) 2.52
Current children cumulated vsize (KiB) 42388

[startup+6.31224 s]
/proc/loadavg: 1.09 1.13 1.05 2/37 18689
/proc/meminfo: memFree=514724/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=39824 CPUtime=6.12
/proc/18682/stat : 18682 (packup) S 18681 18681 1511 34817 1511 4202496 9688 38282 0 0 139 44 375 54 18 0 1 0 4131989 40779776 9330 1283457024 134512640 134752139 4292513648 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/18682/statm: 9956 9330 333 59 0 9120 0
Current children cumulated CPU time (s) 6.12
Current children cumulated vsize (KiB) 42396

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

[startup+6.41225 s]
/proc/loadavg: 1.09 1.13 1.05 2/37 18689
/proc/meminfo: memFree=514724/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=39824 CPUtime=6.12
/proc/18682/stat : 18682 (packup) S 18681 18681 1511 34817 1511 4202496 9688 38282 0 0 139 44 375 54 18 0 1 0 4131989 40779776 9330 1283457024 134512640 134752139 4292513648 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/18682/statm: 9956 9330 333 59 0 9120 0
Current children cumulated CPU time (s) 6.12
Current children cumulated vsize (KiB) 42396

[startup+8.0127 s]
/proc/loadavg: 1.09 1.13 1.05 2/37 18691
/proc/meminfo: memFree=509028/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=39824 CPUtime=6.12
/proc/18682/stat : 18682 (packup) S 18681 18681 1511 34817 1511 4202496 9688 38282 0 0 139 44 375 54 18 0 1 0 4131989 40779776 9330 1283457024 134512640 134752139 4292513648 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/18682/statm: 9956 9330 333 59 0 9120 0
[pid=18690] ppid=18682 vsize=1676 CPUtime=0
/proc/18690/stat : 18690 (sh) S 18682 18681 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 4132605 1716224 124 1283457024 134512640 134593992 4288984304 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/18690/statm: 419 124 108 20 0 46 0
[pid=18691] ppid=18690 vsize=73128 CPUtime=1.84
/proc/18691/stat : 18691 (minisatp_32) R 18690 18681 1511 34817 1511 4202496 22086 0 0 0 167 17 0 0 25 0 1 0 4132606 74883072 15448 1283457024 134512640 135413687 4286763760 18446744073709551615 134705933 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/18691/statm: 18282 15448 107 220 0 18060 0
Current children cumulated CPU time (s) 7.96
Current children cumulated vsize (KiB) 117200

[startup+8.81295 s]
/proc/loadavg: 1.09 1.13 1.05 2/37 18691
/proc/meminfo: memFree=486584/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=39824 CPUtime=6.12
/proc/18682/stat : 18682 (packup) S 18681 18681 1511 34817 1511 4202496 9688 38282 0 0 139 44 375 54 18 0 1 0 4131989 40779776 9330 1283457024 134512640 134752139 4292513648 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/18682/statm: 9956 9330 333 59 0 9120 0
[pid=18690] ppid=18682 vsize=1676 CPUtime=0
/proc/18690/stat : 18690 (sh) S 18682 18681 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 4132605 1716224 124 1283457024 134512640 134593992 4288984304 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/18690/statm: 419 124 108 20 0 46 0
[pid=18691] ppid=18690 vsize=76164 CPUtime=2.64
/proc/18691/stat : 18691 (minisatp_32) R 18690 18681 1511 34817 1511 4202496 24980 0 0 0 247 17 0 0 25 0 1 0 4132606 77991936 16286 1283457024 134512640 135413687 4286763760 18446744073709551615 134649535 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/18691/statm: 19041 16286 109 220 0 18819 0
Current children cumulated CPU time (s) 8.76
Current children cumulated vsize (KiB) 120236

[startup+9.01302 s]
/proc/loadavg: 1.09 1.13 1.05 2/37 18691
/proc/meminfo: memFree=486584/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=39824 CPUtime=6.12
/proc/18682/stat : 18682 (packup) S 18681 18681 1511 34817 1511 4202496 9688 38282 0 0 139 44 375 54 18 0 1 0 4131989 40779776 9330 1283457024 134512640 134752139 4292513648 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/18682/statm: 9956 9330 333 59 0 9120 0
[pid=18690] ppid=18682 vsize=1676 CPUtime=0
/proc/18690/stat : 18690 (sh) S 18682 18681 1511 34817 1511 4202496 147 0 0 0 0 0 0 0 18 0 1 0 4132605 1716224 124 1283457024 134512640 134593992 4288984304 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/18690/statm: 419 124 108 20 0 46 0
[pid=18691] ppid=18690 vsize=76164 CPUtime=2.84
/proc/18691/stat : 18691 (minisatp_32) R 18690 18681 1511 34817 1511 4202496 24990 0 0 0 267 17 0 0 25 0 1 0 4132606 77991936 16296 1283457024 134512640 135413687 4286763760 18446744073709551615 134649574 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/18691/statm: 19041 16296 109 220 0 18819 0
Current children cumulated CPU time (s) 8.96
Current children cumulated vsize (KiB) 120236

[startup+9.10351 s]
/proc/loadavg: 1.09 1.13 1.05 2/37 18691
/proc/meminfo: memFree=486584/1048576 swapFree=0/0
[pid=18681] ppid=18680 vsize=2572 CPUtime=0
/proc/18681/stat : 18681 (packup2mp4tr-0.) S 18680 18681 1511 34817 1511 4202496 378 0 0 0 0 0 0 0 18 0 1 0 4131989 2633728 274 1283457024 134512640 135304128 4294740416 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/18681/statm: 643 274 233 194 0 30 0
[pid=18682] ppid=18681 vsize=39828 CPUtime=9.06
/proc/18682/stat : 18682 (packup) R 18681 18681 1511 34817 1511 4202496 11244 63432 0 0 140 46 648 72 18 0 1 0 4131989 40783872 9344 1283457024 134512640 134752139 4292513648 18446744073709551615 134525596 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/18682/statm: 9957 9344 346 59 0 9121 0
Current children cumulated CPU time (s) 9.06
Current children cumulated vsize (KiB) 42400

Child status: 0
Real time (s): 9.1791
CPU time (s): 9.14457
CPU user time (s): 7.9405
CPU system time (s): 1.20407
CPU usage (%): 99.6238
Max. virtual memory (cumulated for all children) (KiB): 121452

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.9405
system time used= 1.20408
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 82148
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= 20
involuntary context switches= 171

runsolver used 0 second user time and 0 second system time

The end