Created attachment 475614 [details]
Broker log of test "Dura_SyncPubAck" with nanosecond timestamps

Using the -Dsync_ack=true option results in initial periods of slow acknowledges and odd patterns of behaviour. Using a modified perf_report.sh this behaviour can be observed:

<snip>

WARMUP_COUNT=1
MSG_SIZE=128
MSG_COUNT=1000

echo "Test report on " `date +%F`
echo "================================================================================================"
echo "|Test           |System throuput|Producer rate|Consumer Rate|Avg Latency|Min Latency|Max Latency|"
echo "------------------------------------------------------------------------------------------------"

# Test 4 Dura Queue Sync Publish and Ack
run_testcase "Dura_SyncPubAck" \
             "-Damqj.tcpNoDelay=true -Ddurable=true -Dsync_ack=true" \
             "-Damqj.tcpNoDelay=true -Ddurable=true -Dwarmup_count=$WARMUP_COUNT -Dmsg_count=$MSG_COUNT -Dmsg_size=$MSG_SIZE -Dsync_publish=persistent"

</snip>

When run against a c++ broker (with store loaded) on localhost, shows that in the first second of the test, all 1000 messages are produced and consumed. However, it takes a further 18 seconds to acknowledge all the consumed messages (a process that results in the dequeue of the message on the store). Using a modified logger which prints out the realtime clock with nanosecond resolution, it can be seen that there is an approximately 40ms delay between each acknowledge. In the following trace from the broker, I marked each <gap/>; in addition, the string "1D:" is printed each time the store is called to write a dequeue record:

<snip>
1296051838.842267671s debug guest: receiver marked completed: 1549 incomplete: { } unknown-completed: { [1,1549] }
<gap/>
1296051838.881586364s trace RECV [127.0.0.1:43008]: Frame[BEbe; channel=1; {ExecutionSyncBody: }]
1296051838.881618072s trace guest: recv cmd 1550: {ExecutionSyncBody: }
1296051838.881634903s debug guest: receiver marked completed: 1550 incomplete: { } unknown-completed: { [1,1550] }
1296051838.881666611s trace SENT [127.0.0.1:43008]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,1550] }; }]
1296051838.881944295s trace RECV [127.0.0.1:43008]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [269,768] }; }]
1296051838.881960288s debug guest: sender marked completed: { [269,768] }
1296051838.882018325s debug guest: sender confirmed point moved to (769+0)
1296051838.882036483s trace RECV [127.0.0.1:43008]: Frame[BEbe; channel=1; {MessageAcceptBody: transfers={ [768,768] }; }]
1296051838.882049055s trace guest: recv cmd 1551: {MessageAcceptBody: transfers={ [768,768] }; }
 1D:1296051838.882081391s debug DeliveryRecord::setEnded() id=768
1296051838.882090819s debug Accepted 768
1296051838.882124691s debug guest: receiver marked completed: 1551 incomplete: { } unknown-completed: { [1,1551] }
<gap/>
1296051838.921576924s trace RECV [127.0.0.1:43008]: Frame[BEbe; channel=1; {ExecutionSyncBody: }]
1296051838.921624695s trace guest: recv cmd 1552: {ExecutionSyncBody: }
1296051838.921642993s debug guest: receiver marked completed: 1552 incomplete: { } unknown-completed: { [1,1552] }
1296051838.921683570s trace SENT [127.0.0.1:43008]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,1552] }; }]
1296051838.922010422s trace RECV [127.0.0.1:43008]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [269,769] }; }]
1296051838.922026764s debug guest: sender marked completed: { [269,769] }
1296051838.922050301s debug guest: sender confirmed point moved to (770+0)
1296051838.922072440s trace RECV [127.0.0.1:43008]: Frame[BEbe; channel=1; {MessageAcceptBody: transfers={ [769,769] }; }]
1296051838.922085011s trace guest: recv cmd 1553: {MessageAcceptBody: transfers={ [769,769] }; }
 1D:1296051838.922123563s debug DeliveryRecord::setEnded() id=769
1296051838.922132642s debug Accepted 769
1296051838.922173708s debug guest: receiver marked completed: 1553 incomplete: { } unknown-completed: { [1,1553] }
<gap/>
1296051838.961565734s trace RECV [127.0.0.1:43008]: Frame[BEbe; channel=1; {ExecutionSyncBody: }]
1296051838.961587035s trace guest: recv cmd 1554: {ExecutionSyncBody: }
1296051838.961608476s debug guest: receiver marked completed: 1554 incomplete: { } unknown-completed: { [1,1554] }
1296051838.961638018s trace SENT [127.0.0.1:43008]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [1,1554] }; }]
1296051838.961871145s trace RECV [127.0.0.1:43008]: Frame[BEbe; channel=1; {SessionCompletedBody: commands={ [269,770] }; }]
1296051838.961885323s debug guest: sender marked completed: { [269,770] }
1296051838.961895659s debug guest: sender confirmed point moved to (771+0)
1296051838.961911513s trace RECV [127.0.0.1:43008]: Frame[BEbe; channel=1; {MessageAcceptBody: transfers={ [770,770] }; }]
1296051838.961923874s trace guest: recv cmd 1555: {MessageAcceptBody: transfers={ [770,770] }; }
 1D:1296051838.961949645s debug DeliveryRecord::setEnded() id=770
1296051838.961959214s debug Accepted 770
1296051838.961989873s debug guest: receiver marked completed: 1555 incomplete: { } unknown-completed: { [1,1555] }
<gap/>
1296051839.001607359s trace RECV [127.0.0.1:43008]: Frame[BEbe; channel=1; {ExecutionSyncBody: }]
</snip>

What is odd about this is that there it is not consistent - while there is other broker activity (ie message transfers and enqueueing on the producer connection), this delay is not present. Approximately half of the acknowledges (those occurring within the initial bock of message transfers) do not show the delay.

The store itself appears to play no role in this, running the identical scenario against a broker without the store loaded produces an almost identical result.

The attachment shows the c++ broker trace from a 1000-message test. The broker has been modified to print the real-time clock instead of the usual date/time. In addition, the store prints codes as its interface is invoked from the broker:

1*   = Construction of JournalImpl instance
1~   = Destruction of JournalImpl instance
1I   = Initialization of JournalImpl instance
1F   = Flush
1E:  = Enqueue record write
1D:  = Dequeue record write
1Wcb = Write callback (occurs when a buffer which was written to disk completes, and the store calls back to the broker to set all the records within that page to complete status)

The attached file timeline:

1296051804.405684041s:            Broker started
1296051823.778145425s:            Test starts
1296051828.134654748s: [  0.000s] First producer message transfer
1296051828.175620347s: [+ 0.041s] First consumer acknowledge
1296051828.597425639s: [+ 0.463s] Last producer message transfer
1296051828.827183462s: [+ 0.693s] Last consumer message transfer
1296051847.924865980s: [+19.790s] Last consumer acknowledge