Uploaded image for project: 'Blazegraph (by SYSTAP)'
  1. Blazegraph (by SYSTAP)
  2. BLZG-864

Incremental or asynchronous purge of HALog files

    Details

      Description

      A large latency was observed on the leader (bigdata15) and the first follower (bigdata16) following a restart of all services during the first commit. The services had approximately 150,000 HALog files each. Most of these HALog files had been rendered unnecessary by a recent snapshot. Therefore, they were being purged during the commit. This protocol should be modified to either purge the HALogs in an asynchronous thread (with an invariant monitor) or to purge them in blocks of a few hundred to a thousand (each directory contains 1000 HALog files) at a time.

      See https://sourceforge.net/apps/trac/bigdata/ticket/738#comment:39 for context.

        Activity

        Hide
        bryanthompson bryanthompson added a comment -

        Another instance of this was observed in an HA3 configuration for bigdata15,16,17 with bigdata15 as the leader. The HA3 cluster had been quiet (no updates) and had passed the point at which a snapshot and the HALogs pinned by that snapshot could be expired.

        High Availability
        
        The quorum is met.
        3 out of 3 services are joined.
        quorumToken=67, lastValidToken=67
        logicalServiceZPath=/benchmark/com.bigdata.journal.jini.ha.HAJournalServer/HAJournal-1
        HAStatus: Follower, HAReadyToken=67
        Service: serviceId=7e839ae7-9847-492f-b8a2-0260395bb123
        Service: pid=18609
        Service: path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer
        Service: snapshotPolicy=DefaultSnapshotPolicy{timeOfDay=0200, percentLogSize=20%}, countdown=18:35, shouldSnapshot=false
        Service: restorePolicy=DefaultRestorePolicy{minRestoreAge=604800000ms,minSnapshots=1,minRestorePoints=0}
        HAJournal: file=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/bigdata-ha.jnl, commitCounter=5659274, nbytes=19567149056
        
        rootBlock{ rootBlock=0, challisField=5659274, version=3, nextOffset=1207495699961271, localTime=1387143828088 [Sunday, December 15, 2013 4:43:48 PM EST], firstCommitTime=1382905393987 [Sunday, October 27, 2013 4:23:13 PM EDT], lastCommitTime=1387143828029 [Sunday, December 15, 2013 4:43:48 PM EST], commitCounter=5659274, commitRecordAddr={off=NATIVE:-33776056,len=422}, commitRecordIndexAddr={off=NATIVE:-27403533,len=220}, blockSequence=1, quorumToken=67, metaBitsAddr=261717321842879, metaStartAddr=298571, storeType=RW, uuid=cc980e9e-b974-435a-b1a5-18c6ef432d66, offsetBits=42, checksum=1048323258, createTime=1382905368291 [Sunday, October 27, 2013 4:22:48 PM EDT], closeTime=0}
        HALogDir: nfiles=1303644, nbytes=114618466175, path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/HALog, compressorKey=DBS, lastHALogClosed=000000000000005659274, liveLog=000000000000005659275.ha-log
        SnapshotDir: nfiles=7, nbytes=41799875275, path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/snapshot
        SnapshotFile: commitTime=1386193837703 [Wednesday, December 4, 2013 4:50:37 PM EST], commitCounter=4355632, nbytes=5862432697
        SnapshotFile: commitTime=1386659921665 [Tuesday, December 10, 2013 2:18:41 AM EST], commitCounter=4471442, nbytes=5899686670
        SnapshotFile: commitTime=1386833918905 [Thursday, December 12, 2013 2:38:38 AM EST], commitCounter=4843287, nbytes=5965927765
        SnapshotFile: commitTime=1386921491476 [Friday, December 13, 2013 2:58:11 AM EST], commitCounter=5010082, nbytes=5978712405
        SnapshotFile: commitTime=1387004403104 [Saturday, December 14, 2013 2:00:03 AM EST], commitCounter=5245828, nbytes=6012105149
        SnapshotFile: commitTime=1387090803536 [Sunday, December 15, 2013 2:00:03 AM EST], commitCounter=5502109, nbytes=6051130494
        SnapshotFile: commitTime=1387143828029 [Sunday, December 15, 2013 4:43:48 PM EST], commitCounter=5659274, nbytes=6029880095
        com.bigdata.quorum.zk.ZKQuorumImpl@22eba1f5{ k=3, lastValidToken=67, token=67, members=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], pipeline=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], votes={1386168122191=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f]}, joined=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], client=com.bigdata.journal.jini.ha.HAJournalServer$HAQuorumService, serviceId=7e839ae7-9847-492f-b8a2-0260395bb123, listeners=[com.bigdata.journal.jini.ha.HAJournalServer$HAQuorumService$1@1bd5edbc]}
        Quorum Services
        
        http://bigdata15.bigdata.com:8090 : leader, pipelineOrder=0, writePipelineAddr=/192.168.1.15:9090, service=other, extendedRunState={server=Running, quorumService=RunMet @ 5659274, haReady=67, haStatus=Leader, serviceId=c9a3f67f-5d86-44d8-9d30-fd39eda913d4, now=1387455850045}
        http://bigdata17.bigdata.com:8090 : follower, pipelineOrder=1, writePipelineAddr=/192.168.1.17:9090, service=self, extendedRunState={server=Running, quorumService=RunMet @ 5659274, haReady=67, haStatus=Follower, serviceId=7e839ae7-9847-492f-b8a2-0260395bb123, now=1387455850051}
        http://bigdata16.bigdata.com:8090 : follower, pipelineOrder=2, writePipelineAddr=/192.168.1.16:9090, service=other, extendedRunState={server=Running, quorumService=RunMet @ 5659274, haReady=67, haStatus=Follower, serviceId=a49c1863-e31a-4193-969e-84f439dbd54f, now=1387455850060}
        

        The snapshot was not expired since there was no commit activity. To trigger the snapshot expiration, I sent through a small update (1 triple). There was a large latency associated with the synchronous delete of the associated HALog files on the leader (400332ms, which is over 6 minutes of wait time during the commit).

        After the commit, the new state of the quorum shows that a large number of HALog files were deleted. There were 1,303,644 HALog files before the commit and only 815,990 after the commit. 65GB of local storage was reclaimed during this commit and HALog/snapshot purge.

        High Availability
        
        The quorum is met.
        3 out of 3 services are joined.
        quorumToken=67, lastValidToken=67
        logicalServiceZPath=/benchmark/com.bigdata.journal.jini.ha.HAJournalServer/HAJournal-1
        HAStatus: Follower, HAReadyToken=67
        Service: serviceId=7e839ae7-9847-492f-b8a2-0260395bb123
        Service: pid=18609
        Service: path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer
        Service: snapshotPolicy=DefaultSnapshotPolicy{timeOfDay=0200, percentLogSize=20%}, countdown=18:27, shouldSnapshot=false
        Service: restorePolicy=DefaultRestorePolicy{minRestoreAge=604800000ms,minSnapshots=1,minRestorePoints=0}
        HAJournal: file=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/bigdata-ha.jnl, commitCounter=5659275, nbytes=19567149056
        
        rootBlock{ rootBlock=1, challisField=5659275, version=3, nextOffset=1207495699961268, localTime=1387455866572 [Thursday, December 19, 2013 7:24:26 AM EST], firstCommitTime=1382905393987 [Sunday, October 27, 2013 4:23:13 PM EDT], lastCommitTime=1387455866512 [Thursday, December 19, 2013 7:24:26 AM EST], commitCounter=5659275, commitRecordAddr={off=NATIVE:-33776057,len=422}, commitRecordIndexAddr={off=NATIVE:-27402321,len=220}, blockSequence=1, quorumToken=67, metaBitsAddr=261717120516287, metaStartAddr=298571, storeType=RW, uuid=cc980e9e-b974-435a-b1a5-18c6ef432d66, offsetBits=42, checksum=-1223219947, createTime=1382905368291 [Sunday, October 27, 2013 4:22:48 PM EDT], closeTime=0}
        HALogDir: nfiles=815990, nbytes=69269765310, path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/HALog, compressorKey=DBS, lastHALogClosed=000000000000005659275, liveLog=000000000000005659276.ha-log
        SnapshotDir: nfiles=5, nbytes=30037755908, path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/snapshot
        SnapshotFile: commitTime=1386833918905 [Thursday, December 12, 2013 2:38:38 AM EST], commitCounter=4843287, nbytes=5965927765
        SnapshotFile: commitTime=1386921491476 [Friday, December 13, 2013 2:58:11 AM EST], commitCounter=5010082, nbytes=5978712405
        SnapshotFile: commitTime=1387004403104 [Saturday, December 14, 2013 2:00:03 AM EST], commitCounter=5245828, nbytes=6012105149
        SnapshotFile: commitTime=1387090803536 [Sunday, December 15, 2013 2:00:03 AM EST], commitCounter=5502109, nbytes=6051130494
        SnapshotFile: commitTime=1387143828029 [Sunday, December 15, 2013 4:43:48 PM EST], commitCounter=5659274, nbytes=6029880095
        com.bigdata.quorum.zk.ZKQuorumImpl@22eba1f5{ k=3, lastValidToken=67, token=67, members=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], pipeline=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], votes={1386168122191=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f]}, joined=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], client=com.bigdata.journal.jini.ha.HAJournalServer$HAQuorumService, serviceId=7e839ae7-9847-492f-b8a2-0260395bb123, listeners=[com.bigdata.journal.jini.ha.HAJournalServer$HAQuorumService$1@1bd5edbc]}
        Quorum Services
        
        http://bigdata15.bigdata.com:8090 : leader, pipelineOrder=0, writePipelineAddr=/192.168.1.15:9090, service=other, extendedRunState={server=Running, quorumService=RunMet @ 5659275, haReady=67, haStatus=Leader, serviceId=c9a3f67f-5d86-44d8-9d30-fd39eda913d4, now=1387456352168}
        http://bigdata17.bigdata.com:8090 : follower, pipelineOrder=1, writePipelineAddr=/192.168.1.17:9090, service=self, extendedRunState={server=Running, quorumService=RunMet @ 5659275, haReady=67, haStatus=Follower, serviceId=7e839ae7-9847-492f-b8a2-0260395bb123, now=1387456352171}
        http://bigdata16.bigdata.com:8090 : follower, pipelineOrder=2, writePipelineAddr=/192.168.1.16:9090, service=other, extendedRunState={server=Running, quorumService=RunMet @ 5659275, haReady=67, haStatus=Follower, serviceId=a49c1863-e31a-4193-969e-84f439dbd54f, now=1387456352179}
        

        The purge of those files also caused a spike in IO Wait, which jumped from 0% to 6%. At the same time, CPU (user + system) jumped to 20%.

        The purge should be asynchronous and performed using a small thread pool to release HALog files in each of directory (there are 1000 such files per directory).

        Show
        bryanthompson bryanthompson added a comment - Another instance of this was observed in an HA3 configuration for bigdata15,16,17 with bigdata15 as the leader. The HA3 cluster had been quiet (no updates) and had passed the point at which a snapshot and the HALogs pinned by that snapshot could be expired. High Availability The quorum is met. 3 out of 3 services are joined. quorumToken=67, lastValidToken=67 logicalServiceZPath=/benchmark/com.bigdata.journal.jini.ha.HAJournalServer/HAJournal-1 HAStatus: Follower, HAReadyToken=67 Service: serviceId=7e839ae7-9847-492f-b8a2-0260395bb123 Service: pid=18609 Service: path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer Service: snapshotPolicy=DefaultSnapshotPolicy{timeOfDay=0200, percentLogSize=20%}, countdown=18:35, shouldSnapshot=false Service: restorePolicy=DefaultRestorePolicy{minRestoreAge=604800000ms,minSnapshots=1,minRestorePoints=0} HAJournal: file=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/bigdata-ha.jnl, commitCounter=5659274, nbytes=19567149056 rootBlock{ rootBlock=0, challisField=5659274, version=3, nextOffset=1207495699961271, localTime=1387143828088 [Sunday, December 15, 2013 4:43:48 PM EST], firstCommitTime=1382905393987 [Sunday, October 27, 2013 4:23:13 PM EDT], lastCommitTime=1387143828029 [Sunday, December 15, 2013 4:43:48 PM EST], commitCounter=5659274, commitRecordAddr={off=NATIVE:-33776056,len=422}, commitRecordIndexAddr={off=NATIVE:-27403533,len=220}, blockSequence=1, quorumToken=67, metaBitsAddr=261717321842879, metaStartAddr=298571, storeType=RW, uuid=cc980e9e-b974-435a-b1a5-18c6ef432d66, offsetBits=42, checksum=1048323258, createTime=1382905368291 [Sunday, October 27, 2013 4:22:48 PM EDT], closeTime=0} HALogDir: nfiles=1303644, nbytes=114618466175, path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/HALog, compressorKey=DBS, lastHALogClosed=000000000000005659274, liveLog=000000000000005659275.ha-log SnapshotDir: nfiles=7, nbytes=41799875275, path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/snapshot SnapshotFile: commitTime=1386193837703 [Wednesday, December 4, 2013 4:50:37 PM EST], commitCounter=4355632, nbytes=5862432697 SnapshotFile: commitTime=1386659921665 [Tuesday, December 10, 2013 2:18:41 AM EST], commitCounter=4471442, nbytes=5899686670 SnapshotFile: commitTime=1386833918905 [Thursday, December 12, 2013 2:38:38 AM EST], commitCounter=4843287, nbytes=5965927765 SnapshotFile: commitTime=1386921491476 [Friday, December 13, 2013 2:58:11 AM EST], commitCounter=5010082, nbytes=5978712405 SnapshotFile: commitTime=1387004403104 [Saturday, December 14, 2013 2:00:03 AM EST], commitCounter=5245828, nbytes=6012105149 SnapshotFile: commitTime=1387090803536 [Sunday, December 15, 2013 2:00:03 AM EST], commitCounter=5502109, nbytes=6051130494 SnapshotFile: commitTime=1387143828029 [Sunday, December 15, 2013 4:43:48 PM EST], commitCounter=5659274, nbytes=6029880095 com.bigdata.quorum.zk.ZKQuorumImpl@22eba1f5{ k=3, lastValidToken=67, token=67, members=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], pipeline=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], votes={1386168122191=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f]}, joined=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], client=com.bigdata.journal.jini.ha.HAJournalServer$HAQuorumService, serviceId=7e839ae7-9847-492f-b8a2-0260395bb123, listeners=[com.bigdata.journal.jini.ha.HAJournalServer$HAQuorumService$1@1bd5edbc]} Quorum Services http://bigdata15.bigdata.com:8090 : leader, pipelineOrder=0, writePipelineAddr=/192.168.1.15:9090, service=other, extendedRunState={server=Running, quorumService=RunMet @ 5659274, haReady=67, haStatus=Leader, serviceId=c9a3f67f-5d86-44d8-9d30-fd39eda913d4, now=1387455850045} http://bigdata17.bigdata.com:8090 : follower, pipelineOrder=1, writePipelineAddr=/192.168.1.17:9090, service=self, extendedRunState={server=Running, quorumService=RunMet @ 5659274, haReady=67, haStatus=Follower, serviceId=7e839ae7-9847-492f-b8a2-0260395bb123, now=1387455850051} http://bigdata16.bigdata.com:8090 : follower, pipelineOrder=2, writePipelineAddr=/192.168.1.16:9090, service=other, extendedRunState={server=Running, quorumService=RunMet @ 5659274, haReady=67, haStatus=Follower, serviceId=a49c1863-e31a-4193-969e-84f439dbd54f, now=1387455850060} The snapshot was not expired since there was no commit activity. To trigger the snapshot expiration, I sent through a small update (1 triple). There was a large latency associated with the synchronous delete of the associated HALog files on the leader (400332ms, which is over 6 minutes of wait time during the commit). After the commit, the new state of the quorum shows that a large number of HALog files were deleted. There were 1,303,644 HALog files before the commit and only 815,990 after the commit. 65GB of local storage was reclaimed during this commit and HALog/snapshot purge. High Availability The quorum is met. 3 out of 3 services are joined. quorumToken=67, lastValidToken=67 logicalServiceZPath=/benchmark/com.bigdata.journal.jini.ha.HAJournalServer/HAJournal-1 HAStatus: Follower, HAReadyToken=67 Service: serviceId=7e839ae7-9847-492f-b8a2-0260395bb123 Service: pid=18609 Service: path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer Service: snapshotPolicy=DefaultSnapshotPolicy{timeOfDay=0200, percentLogSize=20%}, countdown=18:27, shouldSnapshot=false Service: restorePolicy=DefaultRestorePolicy{minRestoreAge=604800000ms,minSnapshots=1,minRestorePoints=0} HAJournal: file=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/bigdata-ha.jnl, commitCounter=5659275, nbytes=19567149056 rootBlock{ rootBlock=1, challisField=5659275, version=3, nextOffset=1207495699961268, localTime=1387455866572 [Thursday, December 19, 2013 7:24:26 AM EST], firstCommitTime=1382905393987 [Sunday, October 27, 2013 4:23:13 PM EDT], lastCommitTime=1387455866512 [Thursday, December 19, 2013 7:24:26 AM EST], commitCounter=5659275, commitRecordAddr={off=NATIVE:-33776057,len=422}, commitRecordIndexAddr={off=NATIVE:-27402321,len=220}, blockSequence=1, quorumToken=67, metaBitsAddr=261717120516287, metaStartAddr=298571, storeType=RW, uuid=cc980e9e-b974-435a-b1a5-18c6ef432d66, offsetBits=42, checksum=-1223219947, createTime=1382905368291 [Sunday, October 27, 2013 4:22:48 PM EDT], closeTime=0} HALogDir: nfiles=815990, nbytes=69269765310, path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/HALog, compressorKey=DBS, lastHALogClosed=000000000000005659275, liveLog=000000000000005659276.ha-log SnapshotDir: nfiles=5, nbytes=30037755908, path=/root/workspace/BIGDATA_RELEASE_1_3_0/benchmark/HAJournal-1/HAJournalServer/snapshot SnapshotFile: commitTime=1386833918905 [Thursday, December 12, 2013 2:38:38 AM EST], commitCounter=4843287, nbytes=5965927765 SnapshotFile: commitTime=1386921491476 [Friday, December 13, 2013 2:58:11 AM EST], commitCounter=5010082, nbytes=5978712405 SnapshotFile: commitTime=1387004403104 [Saturday, December 14, 2013 2:00:03 AM EST], commitCounter=5245828, nbytes=6012105149 SnapshotFile: commitTime=1387090803536 [Sunday, December 15, 2013 2:00:03 AM EST], commitCounter=5502109, nbytes=6051130494 SnapshotFile: commitTime=1387143828029 [Sunday, December 15, 2013 4:43:48 PM EST], commitCounter=5659274, nbytes=6029880095 com.bigdata.quorum.zk.ZKQuorumImpl@22eba1f5{ k=3, lastValidToken=67, token=67, members=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], pipeline=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], votes={1386168122191=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f]}, joined=[c9a3f67f-5d86-44d8-9d30-fd39eda913d4, 7e839ae7-9847-492f-b8a2-0260395bb123, a49c1863-e31a-4193-969e-84f439dbd54f], client=com.bigdata.journal.jini.ha.HAJournalServer$HAQuorumService, serviceId=7e839ae7-9847-492f-b8a2-0260395bb123, listeners=[com.bigdata.journal.jini.ha.HAJournalServer$HAQuorumService$1@1bd5edbc]} Quorum Services http://bigdata15.bigdata.com:8090 : leader, pipelineOrder=0, writePipelineAddr=/192.168.1.15:9090, service=other, extendedRunState={server=Running, quorumService=RunMet @ 5659275, haReady=67, haStatus=Leader, serviceId=c9a3f67f-5d86-44d8-9d30-fd39eda913d4, now=1387456352168} http://bigdata17.bigdata.com:8090 : follower, pipelineOrder=1, writePipelineAddr=/192.168.1.17:9090, service=self, extendedRunState={server=Running, quorumService=RunMet @ 5659275, haReady=67, haStatus=Follower, serviceId=7e839ae7-9847-492f-b8a2-0260395bb123, now=1387456352171} http://bigdata16.bigdata.com:8090 : follower, pipelineOrder=2, writePipelineAddr=/192.168.1.16:9090, service=other, extendedRunState={server=Running, quorumService=RunMet @ 5659275, haReady=67, haStatus=Follower, serviceId=a49c1863-e31a-4193-969e-84f439dbd54f, now=1387456352179} The purge of those files also caused a spike in IO Wait, which jumped from 0% to 6%. At the same time, CPU (user + system) jumped to 20%. The purge should be asynchronous and performed using a small thread pool to release HALog files in each of directory (there are 1000 such files per directory).
        Hide
        bryanthompson bryanthompson added a comment -

        I have modified HALogNexus to release the HALog files asynchronously. This causes some problems in the existing unit tests, so I have added a configuration parameter that may be used to specify a synchronous HALog release timeout
        - this defaults to ZERO, but may be increased as desired (in exchange for latency in 2-phase commits) or as necessary for the existing tests, some of which assume that HALog files are released synchronously at the 2-phase commit.

        The expected behavior should now be that HALog files are asynchronously release starting with the first 2-phase commit in which the corresponding commit point is reclaimable. The release of HALog files will continue until the specified first commit point that may not be released, or until an invariant is violated. Under sustained commits with concurrent releases, any commit in which the task to release HALog files is longer running will start a new such task with a new earliest commit point that may not be released.

        Changes are to:

        • HALogNexus: now submits a task to release the HALog files. There can be at most one instance of this task running for a given HAJournal. The task is wrapped by the FutureTaskInvariantMon and will be cancelled if the service is no longer joined with the met quorum.
        • HAJournalServer: A new configuration parameter exists to control the maximum delay for releasing the HALog files (default is ZERO milliseconds).
        • TestHARestorePolicy: This was modified to raise the timeout for the synchronous purge of the HALogs so the test assumptions would remain valid.

        Note: The HAJournalServer.ConfigurationOptions.HA_LOG_PURGE_TIMEOUT defaults to zero. This is probably what we always want. However, the existence of this option allows us to revert to the old behavior using a configuration change or by changing the default.

        Committed revision r7816.

        Show
        bryanthompson bryanthompson added a comment - I have modified HALogNexus to release the HALog files asynchronously. This causes some problems in the existing unit tests, so I have added a configuration parameter that may be used to specify a synchronous HALog release timeout - this defaults to ZERO, but may be increased as desired (in exchange for latency in 2-phase commits) or as necessary for the existing tests, some of which assume that HALog files are released synchronously at the 2-phase commit. The expected behavior should now be that HALog files are asynchronously release starting with the first 2-phase commit in which the corresponding commit point is reclaimable. The release of HALog files will continue until the specified first commit point that may not be released, or until an invariant is violated. Under sustained commits with concurrent releases, any commit in which the task to release HALog files is longer running will start a new such task with a new earliest commit point that may not be released. Changes are to: HALogNexus: now submits a task to release the HALog files. There can be at most one instance of this task running for a given HAJournal. The task is wrapped by the FutureTaskInvariantMon and will be cancelled if the service is no longer joined with the met quorum. HAJournalServer: A new configuration parameter exists to control the maximum delay for releasing the HALog files (default is ZERO milliseconds). TestHARestorePolicy: This was modified to raise the timeout for the synchronous purge of the HALogs so the test assumptions would remain valid. Note: The HAJournalServer.ConfigurationOptions.HA_LOG_PURGE_TIMEOUT defaults to zero. This is probably what we always want. However, the existence of this option allows us to revert to the old behavior using a configuration change or by changing the default. Committed revision r7816.
        Hide
        bryanthompson bryanthompson added a comment -

        Also wrapped as assertCondition one test that was checking the HALog outcome status in TestHA3JournalServer.

        Committed revision r7817.

        This is committed to CI for validation. There may be some other tests that need to be tweaked to work correctly with these commits.

        We will need to also verify that the latency is gone for commits when a large number of HALog files need to be purged. The easy way to do this is to run an HA3 cluster, stop one service, apply several 1000 commit points, then restart the service while continuing to apply commits. There should be no additional latency once the 3rd service catches up and joins and the HALog files should be purged asynchronously. The asynchronous purge can be verified from the /status page on the services. This procedure relies on the fact that we do not release HALog files unless the quorum is fully met.

        Show
        bryanthompson bryanthompson added a comment - Also wrapped as assertCondition one test that was checking the HALog outcome status in TestHA3JournalServer. Committed revision r7817. This is committed to CI for validation. There may be some other tests that need to be tweaked to work correctly with these commits. We will need to also verify that the latency is gone for commits when a large number of HALog files need to be purged. The easy way to do this is to run an HA3 cluster, stop one service, apply several 1000 commit points, then restart the service while continuing to apply commits. There should be no additional latency once the 3rd service catches up and joins and the HALog files should be purged asynchronously. The asynchronous purge can be verified from the /status page on the services. This procedure relies on the fact that we do not release HALog files unless the quorum is fully met.
        Hide
        bryanthompson bryanthompson added a comment -

        There are a few new failures in CI. These are presumably due to the asynchronous purge of HALog files, but that needs to be checked in depth. The fix for that is either to await the desired number of HALogs in assertCondition(), to remove the check, or to specify the override as in TestHA3RestorePolicy.

                        "com.bigdata.journal.jini.ha.HAJournalServer.HALogPurgeTimeout="+Long.MAX_VALUE+"L" // force synchronous purge.
        
        
        Show
        bryanthompson bryanthompson added a comment - There are a few new failures in CI. These are presumably due to the asynchronous purge of HALog files, but that needs to be checked in depth. The fix for that is either to await the desired number of HALogs in assertCondition(), to remove the check, or to specify the override as in TestHA3RestorePolicy. "com.bigdata.journal.jini.ha.HAJournalServer.HALogPurgeTimeout="+Long.MAX_VALUE+"L" // force synchronous purge.
        Hide
        bryanthompson bryanthompson added a comment -

        The CI errors appear to have been resolved.

        Show
        bryanthompson bryanthompson added a comment - The CI errors appear to have been resolved.

          People

          • Assignee:
            bryanthompson bryanthompson
            Reporter:
            bryanthompson bryanthompson
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: