Quantum| Space Reclamation (BPGC) -- Understanding what is being logged |
Introduction
I thought it would be useful information if everyone had the commands to find in the our logs the specific starts and ends to each stage of bpgc. Prior to 2.2.x bpgc ran in 4 stages with stges 1 and 4 being a "compaction" stage. In 2.2.x and later stages 1 and 4 were removed and now just stages 2 and 3 run. For that reason I have outlined what you will see in the logs for all 4 stages but with firmware nwer than 2.2 you can ignor stages 1 and 4. This article can be useful when determining what exactly is running when customer complains of slow ingest or replication or if you need to timeline a missing tag issue.
Taken from a 2.1.1 system (or LEGACY MODE in 2.2.x or later):
Find the start of BPGC (scheduled or manually started)
#grep “Starting Scheduled GC” /var/log/DXi/tsunami.log
Find the start of Stages 1 or 4 - Compaction
#grep “Starting GC compaction” /var/log/DXi/tsunami.log
Find the end of Stages 1 or 4 - Compaction
#grep “cleanupHoldList completed successfully” /var/log/DXi/tsunami.log
or better
#grep “Compacting blockpool (100% complete)” /var/log/messages
*Note: You can [#grep Compacting /var/log/messages] to see all of the Compaction stage
Find the start of Stage 2 – Create Delete Candidates List
#grep “deletion candidates” /var/log/DXi/tsunami.log
Find the end of Stage 2 - Create Delete Candidates List
#grep “tags to delete” /var/log/DXi/tsunami.log
*Note: Make note of the process IDs for each of the 4 bpgc processes. This is how you can track the progress of a particular stream by grepping that number.
i.e. #grep 1219656000 /var/log/DXi/tsunami.log
[root@ppodxi8500a ~]# grep 1219656000 /var/log/DXi/tsunami.log
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(563) [bpgc] doProcess() - {1219656000} Found 23875 tags to delete
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(526) [bpgc] doProcess() - {1219656000} Starting GC deletions
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 1.00%
INFO - 09/25/12-09:29:50 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 16.80%
INFO - 09/25/12-10:21:20 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 25.78%
INFO - 09/25/12-12:12:10 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 54.00%
INFO - 09/25/12-12:22:53 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 56.06%
INFO - 09/25/12-12:42:55 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 62.25%
INFO - 09/25/12-13:12:59 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 70.46%
INFO - 09/25/12-14:07:22 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 85.44%
INFO - 09/25/12-15:01:19 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 100.00%
INFO - 09/25/12-15:01:19 - bpgc DeleteThread.cpp(439) [bpgc] deleteCandidates() - {1219656000} Successfully deleted 23875 tags
Find the start of Stage 3 - Decrease reference count on tags
#grep “Starting GC deletions” /var/log/DXi/tsunami.log
or
#grep “GC Delete Progress is currently: 1.00%” /var/log/DXi/tsunami.log
Find the end of Stage 3 - Decrease reference count on tags
#grep “GC Delete Progress is currently: 100.00%” /var/log/DXi/tsunami.log
*Note: This section is broken down by the stream identifier as well. In most cases you can just [grep % /var/log/DXi/tsunami.log] and see all stage 3 progress for all streams.
----------------------------------------------------------------------------------------------------
Most of what you will need is in the tsunami.log file however it is easier to see the progress of the Compaction stage by looking in the messages file. You can pull out all the bpgc info from the tsunami.log file (or tsunami.log* if you want all the tsunami logs) by doing the following:
#grep " - bpgc " /var/log/DXi/tsunami.log > /scratch/bpgc.out
Here is the entire bpgc process when run.
INFO - 09/25/12-08:00:26 - bpgc SchedulerThread.cpp(413) [bpgc] doProcess() - {1167206720} Starting Scheduled GC
INFO - 09/25/12-08:00:26 - bpgc SchedulerThread.cpp(240) [bpgc] incrementSchedule() - {1167206720} GC Scheduler - Next Start Time is now: Wed Sep 26 08:00:00 2012
INFO - 09/25/12-08:00:26 - bpgc SysUtil.cpp(549) [bpgc] signal() - Sending signal:10 to pid:2895
INFO - 09/25/12-08:00:26 - bpgc GCDaemon.cpp(365) [bpgc] interruptWait() - Start Reclamation Request detected, stopping wait
INFO - 09/25/12-08:00:31 - bpgc CleanupStrategyFactory.cpp(122) [bpgc] create() - Selecting the Target Cleanup Strategy
INFO - 09/25/12-08:00:31 - bpgc CompactThread.cpp(318) [bpgc] doProcess() - {1156716864} Starting GC compaction
INFO - 09/25/12-08:00:31 - bpgc CompactThread.cpp(224) [bpgc] updateStatusFile() - {1156716864} 0 bytes of 27365268366 reclaimed (progress: 1.00)
INFO - 09/25/12-08:01:47 - bpgc CompactThread.cpp(224) <log message repeated 1 times>
INFO - 09/25/12-08:01:47 - bpgc ReconcileThread.cpp(1121) [bpgc] doProcess() - {1146227008} Reconciling Blockpool Tags
INFO - 09/25/12-08:01:47 - bpgc ReconcileThread.cpp(126) [bpgc] dumpBlockpoolTags() - {1146227008} Dumping the blockpool tags
INFO - 09/25/12-08:04:03 - bpgc ReconcileThread.cpp(257) [bpgc] dumpReferencedTags() - {1146227008} Dumping referenced tags
INFO - 09/25/12-08:04:03 - bpgc GCUtil.cpp(1998) [bpgc] callCleanupHoldList() - Calling cleanupHoldList
INFO - 09/25/12-08:04:03 - bpgc GCUtil.cpp(2002) [bpgc] callCleanupHoldList() - Call to cleanupHoldList completed successfully
INFO - 09/25/12-08:29:02 - bpgc ReconcileThread.cpp(836) [bpgc] determineCandidates() - {1146227008} Determining the blockpool deletion candidates
INFO - 09/25/12-08:29:02 - bpgc FileUtil.cpp(352) [bpgc] sortFile() - Sorting file /data/hurricane/bpgc/blockpooltags
INFO - 09/25/12-08:29:08 - bpgc FileUtil.cpp(352) [bpgc] sortFile() - Sorting file /data/hurricane/bpgc/referencedtags
INFO - 09/25/12-08:29:21 - bpgc ReconcileThread.cpp(1216) [bpgc] doProcess() - {1146227008} Reconciling Complete
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(563) [bpgc] doProcess() - {1219656000} Found 23875 tags to delete
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(563) [bpgc] doProcess() - {1209166144} Found 23875 tags to delete
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(563) [bpgc] doProcess() - {1240635712} Found 23874 tags to delete
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(563) [bpgc] doProcess() - {1230145856} Found 23874 tags to delete
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(526) [bpgc] doProcess() - {1219656000} Starting GC deletions
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(526) [bpgc] doProcess() - {1230145856} Starting GC deletions
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(526) [bpgc] doProcess() - {1209166144} Starting GC deletions
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(526) [bpgc] doProcess() - {1240635712} Starting GC deletions
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 1.00%
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 1.00%
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 1.00%
INFO - 09/25/12-08:29:21 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1240635712} GC Delete Progress is currently: 1.00%
INFO - 09/25/12-08:39:22 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 3.06%
INFO - 09/25/12-08:49:23 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 6.33%
INFO - 09/25/12-08:59:24 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 9.64%
INFO - 09/25/12-09:09:25 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 12.73%
INFO - 09/25/12-09:19:26 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 14.74%
INFO - 09/25/12-09:29:50 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 16.80%
INFO - 09/25/12-09:39:51 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1240635712} GC Delete Progress is currently: 18.46%
INFO - 09/25/12-09:49:52 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 19.93%
INFO - 09/25/12-09:59:53 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 22.92%
INFO - 09/25/12-10:09:54 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 24.59%
INFO - 09/25/12-10:21:20 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 25.78%
INFO - 09/25/12-10:31:21 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 26.79%
INFO - 09/25/12-10:41:22 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1240635712} GC Delete Progress is currently: 29.14%
INFO - 09/25/12-10:51:23 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 30.99%
INFO - 09/25/12-11:01:24 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 34.03%
INFO - 09/25/12-11:11:25 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1240635712} GC Delete Progress is currently: 38.18%
INFO - 09/25/12-11:21:26 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1240635712} GC Delete Progress is currently: 40.53%
INFO - 09/25/12-11:32:06 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 41.83%
INFO - 09/25/12-11:42:07 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 44.46%
INFO - 09/25/12-11:52:08 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 48.12%
INFO - 09/25/12-12:02:09 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 51.01%
INFO - 09/25/12-12:12:10 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 54.00%
INFO - 09/25/12-12:22:53 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 56.06%
INFO - 09/25/12-12:32:54 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1240635712} GC Delete Progress is currently: 59.65%
INFO - 09/25/12-12:42:55 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 62.25%
INFO - 09/25/12-12:52:56 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 63.55%
INFO - 09/25/12-13:02:58 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 66.54%
INFO - 09/25/12-13:12:59 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 70.46%
INFO - 09/25/12-13:23:02 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 73.24%
INFO - 09/25/12-13:33:03 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1240635712} GC Delete Progress is currently: 77.51%
INFO - 09/25/12-13:44:02 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 79.01%
INFO - 09/25/12-13:57:21 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 82.17%
INFO - 09/25/12-14:07:22 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 85.44%
INFO - 09/25/12-14:17:35 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1240635712} GC Delete Progress is currently: 87.69%
INFO - 09/25/12-14:27:36 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 90.35%
INFO - 09/25/12-14:37:37 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 92.59%
INFO - 09/25/12-14:47:38 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1240635712} GC Delete Progress is currently: 96.24%
INFO - 09/25/12-14:57:39 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 98.61%
INFO - 09/25/12-14:59:10 - bpgc DeleteThread.cpp(439) [bpgc] deleteCandidates() - {1240635712} Successfully deleted 23874 tags
INFO - 09/25/12-14:59:10 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1240635712} GC Delete Progress is currently: 100.00%
INFO - 09/25/12-15:01:07 - bpgc DeleteThread.cpp(439) [bpgc] deleteCandidates() - {1230145856} Successfully deleted 23874 tags
INFO - 09/25/12-15:01:07 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1230145856} GC Delete Progress is currently: 100.00%
INFO - 09/25/12-15:01:19 - bpgc DeleteThread.cpp(439) [bpgc] deleteCandidates() - {1219656000} Successfully deleted 23875 tags
INFO - 09/25/12-15:01:19 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1219656000} GC Delete Progress is currently: 100.00%
INFO - 09/25/12-15:02:02 - bpgc DeleteThread.cpp(439) [bpgc] deleteCandidates() - {1209166144} Successfully deleted 23875 tags
INFO - 09/25/12-15:02:02 - bpgc DeleteThread.cpp(180) [bpgc] updateStatusFile() - {1209166144} GC Delete Progress is currently: 100.00%
INFO - 09/25/12-15:02:02 - bpgc CompactThread.cpp(318) [bpgc] doProcess() - {1156716864} Starting GC compaction
INFO - 09/25/12-15:02:02 - bpgc CompactThread.cpp(224) [bpgc] updateStatusFile() - {1156716864} 0 bytes of 899808917589 reclaimed (progress: 1.00)
INFO - 09/25/12-15:13:05 - bpgc CompactThread.cpp(224) [bpgc] updateStatusFile() - {1156716864} 6321280017 bytes of 899808917589 reclaimed (progress: 1.00)
INFO - 09/25/12-15:23:37 - bpgc CompactThread.cpp(224) [bpgc] updateStatusFile() - {1156716864} 21262925710 bytes of 899808917589 reclaimed (progress: 2.36)
INFO - 09/25/12-15:34:51 - bpgc CompactThread.cpp(224) [bpgc] updateStatusFile() - {1156716864} 31055496043 bytes of 899808917589 reclaimed (progress: 3.45)
INFO - 09/25/12-15:45:51 - bpgc CompactThread.cpp(224) [bpgc] updateStatusFile() - {1156716864} 50321585972 bytes of 899808917589 reclaimed (progress: 5.59)
INFO - 09/25/12-15:56:22 - bpgc CompactThread.cpp(224) [bpgc] updateStatusFile() - {1156716864} 66801706034 bytes of 899808917589 reclaimed (progress: 7.42)
INFO - 09/25/12-16:06:54 - bpgc CompactThread.cpp(224) [bpgc] updateStatusFile() - {1156716864} 86099351993 bytes of 899808917589 reclaimed (progress: 9.57)
INFO - 09/25/12-16:18:46 - bpgc CompactThread.cpp(224) [bpgc] updateStatusFile() - {1156716864} 97476701630 bytes of 899808917589 reclaimed (progress: 10.83)
In Conclusion
Knowing when bpgc is running and what stage it is in is very useful in identifying ingest or replication performance issues. Often times when you see a healthcheck error that tags were missing and not recovered it is because healthcheck was run after bpgc stage 2 finished but before stage 3 completes. For this instance I always rerun healthcheck to see if the error reoccurs.
This page was generated by the BrainKeeper Enterprise Wiki, © 2018 |