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/7bf50d1c-9b1b-11df-8b50-00163e46d37a.cudf.dudf-real.log.runsolver ./packup2mp4tr-0.6 /home/misc2010/data/2011/dudf-real//7bf50d1c-9b1b-11df-8b50-00163e46d37a.cudf /home/misc2010/tmp/201108241238/packup2mp4tr-0.6/7bf50d1c-9b1b-11df-8b50-00163e46d37a.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.19 1.13 1.10 5/34 26980
/proc/meminfo: memFree=315148/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) R 26978 26979 1511 34817 1511 4202496 360 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=2572 CPUtime=0
/proc/26980/stat : 26980 (packup2mp4tr-0.) R 26979 26979 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 41 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65538 4 84480 0 0 0 17 0 0 0 0
/proc/26980/statm: 643 41 0 194 0 30 0

[startup+0.213461 s]
/proc/loadavg: 1.19 1.13 1.10 5/34 26980
/proc/meminfo: memFree=315148/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=10652 CPUtime=0.2
/proc/26980/stat : 26980 (packup) R 26979 26979 1511 34817 1511 4202496 2148 0 0 0 18 2 0 0 25 0 1 0 4843474 10907648 2077 1283457024 134512640 134752139 4287081024 18446744073709551615 134681714 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26980/statm: 2663 2077 286 59 0 1827 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 13224

[startup+0.303475 s]
/proc/loadavg: 1.19 1.13 1.10 5/34 26980
/proc/meminfo: memFree=315148/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=13120 CPUtime=0.3
/proc/26980/stat : 26980 (packup) R 26979 26979 1511 34817 1511 4202496 2757 0 0 0 28 2 0 0 25 0 1 0 4843474 13434880 2686 1283457024 134512640 134752139 4287081024 18446744073709551615 134681791 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26980/statm: 3280 2686 286 59 0 2444 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15692

[startup+0.413495 s]
/proc/loadavg: 1.19 1.13 1.10 5/34 26980
/proc/meminfo: memFree=315148/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=16024 CPUtime=0.4
/proc/26980/stat : 26980 (packup) R 26979 26979 1511 34817 1511 4202496 3491 0 0 0 38 2 0 0 25 0 1 0 4843474 16408576 3420 1283457024 134512640 134752139 4287081024 18446744073709551615 134681560 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26980/statm: 4006 3420 286 59 0 3170 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 18596

[startup+0.703552 s]
/proc/loadavg: 1.19 1.13 1.10 5/34 26980
/proc/meminfo: memFree=315148/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=23084 CPUtime=0.69
/proc/26980/stat : 26980 (packup) R 26979 26979 1511 34817 1511 4202496 5256 0 0 0 65 4 0 0 25 0 1 0 4843474 23638016 5185 1283457024 134512640 134752139 4287081024 18446744073709551615 134694861 0 0 18944 8192 0 0 0 17 0 0 0 0
/proc/26980/statm: 5771 5185 286 59 0 4935 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 25656

[startup+1.50368 s]
/proc/loadavg: 1.19 1.13 1.10 2/35 26981
/proc/meminfo: memFree=281656/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=35884 CPUtime=1.21
/proc/26980/stat : 26980 (packup) S 26979 26979 1511 34817 1511 4202496 8492 0 0 0 108 13 0 0 25 0 1 0 4843474 36745216 8420 1283457024 134512640 134752139 4287081024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26980/statm: 8971 8420 324 59 0 8135 0
Current children cumulated CPU time (s) 1.21
Current children cumulated vsize (KiB) 38456

[startup+3.10664 s]
/proc/loadavg: 1.19 1.13 1.10 2/37 26985
/proc/meminfo: memFree=276292/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=37320 CPUtime=2.12
/proc/26980/stat : 26980 (packup) S 26979 26979 1511 34817 1511 4202496 9123 4510 0 0 118 22 62 10 19 0 1 0 4843474 38215680 8657 1283457024 134512640 134752139 4287081024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26980/statm: 9330 8657 332 59 0 8494 0
[pid=26984] ppid=26980 vsize=1676 CPUtime=0.01
/proc/26984/stat : 26984 (sh) S 26980 26979 1511 34817 1511 4202496 146 0 0 0 0 1 0 0 19 0 1 0 4843688 1716224 124 1283457024 134512640 134593992 4292532304 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26984/statm: 419 124 108 20 0 46 0
[pid=26985] ppid=26984 vsize=35380 CPUtime=0.99
/proc/26985/stat : 26985 (minisatp_32) R 26984 26979 1511 34817 1511 4202496 10681 0 0 0 90 9 0 0 25 0 1 0 4843689 36229120 8033 1283457024 134512640 135413687 4294793872 18446744073709551615 134686504 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26985/statm: 8845 8033 108 220 0 8623 0
Current children cumulated CPU time (s) 3.12
Current children cumulated vsize (KiB) 76948

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

[startup+3.20665 s]
/proc/loadavg: 1.19 1.13 1.10 2/37 26985
/proc/meminfo: memFree=276292/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=37320 CPUtime=2.12
/proc/26980/stat : 26980 (packup) S 26979 26979 1511 34817 1511 4202496 9123 4510 0 0 118 22 62 10 19 0 1 0 4843474 38215680 8657 1283457024 134512640 134752139 4287081024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26980/statm: 9330 8657 332 59 0 8494 0
[pid=26984] ppid=26980 vsize=1676 CPUtime=0.01
/proc/26984/stat : 26984 (sh) S 26980 26979 1511 34817 1511 4202496 146 0 0 0 0 1 0 0 19 0 1 0 4843688 1716224 124 1283457024 134512640 134593992 4292532304 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26984/statm: 419 124 108 20 0 46 0
[pid=26985] ppid=26984 vsize=35164 CPUtime=1.09
/proc/26985/stat : 26985 (minisatp_32) R 26984 26979 1511 34817 1511 4202496 11763 0 0 0 100 9 0 0 25 0 1 0 4843689 36007936 8080 1283457024 134512640 135413687 4294793872 18446744073709551615 134686457 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26985/statm: 8791 8080 108 220 0 8569 0
Current children cumulated CPU time (s) 3.22
Current children cumulated vsize (KiB) 76732

[startup+4.80689 s]
/proc/loadavg: 1.17 1.13 1.10 2/35 26987
/proc/meminfo: memFree=280772/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=37328 CPUtime=4.6
/proc/26980/stat : 26980 (packup) S 26979 26979 1511 34817 1511 4202496 9244 21991 0 0 134 43 255 28 16 0 1 0 4843474 38223872 8663 1283457024 134512640 134752139 4287081024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26980/statm: 9332 8663 332 59 0 8496 0
Current children cumulated CPU time (s) 4.6
Current children cumulated vsize (KiB) 39900

[startup+5.60708 s]
/proc/loadavg: 1.17 1.13 1.10 2/37 26989
/proc/meminfo: memFree=251244/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=37328 CPUtime=4.6
/proc/26980/stat : 26980 (packup) S 26979 26979 1511 34817 1511 4202496 9244 21991 0 0 134 43 255 28 16 0 1 0 4843474 38223872 8663 1283457024 134512640 134752139 4287081024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26980/statm: 9332 8663 332 59 0 8496 0
[pid=26988] ppid=26980 vsize=1668 CPUtime=0
/proc/26988/stat : 26988 (sh) S 26980 26979 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 16 0 1 0 4843937 1708032 123 1283457024 134512640 134593992 4286597808 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26988/statm: 417 123 108 20 0 44 0
[pid=26989] ppid=26988 vsize=38468 CPUtime=1.02
/proc/26989/stat : 26989 (minisatp_32) R 26988 26979 1511 34817 1511 4202496 10754 0 0 0 96 6 0 0 20 0 1 0 4843937 39391232 8164 1283457024 134512640 135413687 4286882576 18446744073709551615 134686313 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26989/statm: 9617 8164 108 220 0 9395 0
Current children cumulated CPU time (s) 5.62
Current children cumulated vsize (KiB) 80036

[startup+6.00723 s]
/proc/loadavg: 1.17 1.13 1.10 2/37 26989
/proc/meminfo: memFree=251244/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=37328 CPUtime=4.6
/proc/26980/stat : 26980 (packup) S 26979 26979 1511 34817 1511 4202496 9244 21991 0 0 134 43 255 28 16 0 1 0 4843474 38223872 8663 1283457024 134512640 134752139 4287081024 18446744073709551615 4294960130 0 65536 18950 8192 18446744071564329979 0 0 17 0 0 0 0
/proc/26980/statm: 9332 8663 332 59 0 8496 0
[pid=26988] ppid=26980 vsize=1668 CPUtime=0
/proc/26988/stat : 26988 (sh) S 26980 26979 1511 34817 1511 4202496 145 0 0 0 0 0 0 0 16 0 1 0 4843937 1708032 123 1283457024 134512640 134593992 4286597808 18446744073709551615 4294960130 0 0 18944 2 18446744071564329979 0 0 17 0 0 0 0
/proc/26988/statm: 417 123 108 20 0 44 0
[pid=26989] ppid=26988 vsize=41180 CPUtime=1.42
/proc/26989/stat : 26989 (minisatp_32) R 26988 26979 1511 34817 1511 4202496 13587 0 0 0 134 8 0 0 21 0 1 0 4843937 42168320 8994 1283457024 134512640 135413687 4286882576 18446744073709551615 134992593 0 0 18944 0 0 0 0 17 0 0 0 0
/proc/26989/statm: 10295 8994 108 220 0 10073 0
Current children cumulated CPU time (s) 6.02
Current children cumulated vsize (KiB) 82748

[startup+6.21403 s]
/proc/loadavg: 1.17 1.13 1.10 2/37 26989
/proc/meminfo: memFree=251244/1048576 swapFree=0/0
[pid=26979] ppid=26978 vsize=2572 CPUtime=0
/proc/26979/stat : 26979 (packup2mp4tr-0.) S 26978 26979 1511 34817 1511 4202496 377 0 0 0 0 0 0 0 25 0 1 0 4843474 2633728 274 1283457024 134512640 135304128 4288687104 18446744073709551615 4294960130 0 65536 4 84482 18446744071564329979 0 0 17 0 0 0 0
/proc/26979/statm: 643 274 233 194 0 30 0
[pid=26980] ppid=26979 vsize=0 CPUtime=6.22
/proc/26980/stat : 26980 (packup) D 26979 26979 1511 34817 1511 4202500 17220 35785 0 0 142 45 399 36 15 0 1 0 4843474 0 0 1283457024 0 0 0 0 0 0 0 18944 8192 18446744071696440003 0 0 17 0 0 0 0
/proc/26980/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.22
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 6.22287
CPU time (s): 6.23639
CPU user time (s): 5.42034
CPU system time (s): 0.816051
CPU usage (%): 100.217
Max. virtual memory (cumulated for all children) (KiB): 84424

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 5.42034
system time used= 0.816051
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 53392
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= 122

runsolver used 0.012 second user time and 0 second system time

The end