--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Wed Mar 15 10:25:37 2017 -0400
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Thu Mar 16 09:05:20 2017 +0100
@@ -1378,10 +1378,9 @@
       }
       _verifier->check_bitmaps("Full GC End");
 
-      // Start a new incremental collection set for the next pause
-      collection_set()->start_incremental_building();
-
-      clear_cset_fast_test();
+      double start = os::elapsedTime();
+      start_new_collection_set();
+      g1_policy()->phase_times()->record_start_new_cset_time_ms((os::elapsedTime() - start) * 1000.0);
 
       _allocator->init_mutator_alloc_region();
 
@@ -2694,9 +2693,12 @@
 void G1CollectedHeap::gc_prologue(bool full /* Ignored */) {
   // always_do_update_barrier = false;
   assert(InlineCacheBuffer::is_empty(), "should have cleaned up ICBuffer");
+
+  double start = os::elapsedTime();
   // Fill TLAB's and such
   accumulate_statistics_all_tlabs();
   ensure_parsability(true);
+  g1_policy()->phase_times()->record_prepare_tlab_time_ms((os::elapsedTime() - start) * 1000.0);
 
   g1_rem_set()->print_periodic_summary_info("Before GC RS summary", total_collections());
 }
@@ -2713,7 +2715,10 @@
 #endif
   // always_do_update_barrier = true;
 
+  double start = os::elapsedTime();
   resize_all_tlabs();
+  g1_policy()->phase_times()->record_resize_tlab_time_ms((os::elapsedTime() - start) * 1000.0);
+
   allocation_context_stats().update(full);
 
   // We have just completed a GC. Update the soft reference
@@ -2996,6 +3001,15 @@
   }
 };
 
+void G1CollectedHeap::start_new_collection_set() {
+  collection_set()->start_incremental_building();
+
+  clear_cset_fast_test();
+
+  guarantee(_eden.length() == 0, "eden should have been cleared");
+  g1_policy()->transfer_survivors_to_cset(survivor());
+}
+
 bool
 G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
   assert_at_safepoint(true /* should_be_vm_thread */);
@@ -3198,13 +3212,7 @@
         _survivor_evac_stats.adjust_desired_plab_sz();
         _old_evac_stats.adjust_desired_plab_sz();
 
-        // Start a new incremental collection set for the next pause.
-        collection_set()->start_incremental_building();
-
-        clear_cset_fast_test();
-
-        guarantee(_eden.length() == 0, "eden should have been cleared");
-        g1_policy()->transfer_survivors_to_cset(survivor());
+        start_new_collection_set();
 
         if (evacuation_failed()) {
           set_used(recalculate_used());
@@ -4522,7 +4530,9 @@
 
   redirty_logged_cards();
 #if defined(COMPILER2) || INCLUDE_JVMCI
+  double start = os::elapsedTime();
   DerivedPointerTable::update_pointers();
+  g1_policy()->phase_times()->record_derived_pointer_table_update_time((os::elapsedTime() - start) * 1000.0);
 #endif
   g1_policy()->print_age_table();
 }

--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp	Wed Mar 15 10:25:37 2017 -0400
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp	Thu Mar 16 09:05:20 2017 +0100
@@ -159,6 +159,8 @@
   HeapRegionSet _humongous_set;
 
   void eagerly_reclaim_humongous_regions();
+  // Start a new incremental collection set for the next pause.
+  void start_new_collection_set();
 
   // The number of regions we could create by expansion.
   uint _expansion_regions;

--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp	Wed Mar 15 10:25:37 2017 -0400
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp	Thu Mar 16 09:05:20 2017 +0100
@@ -112,6 +112,9 @@
   _cur_evac_fail_restore_remsets = 0.0;
   _cur_evac_fail_remove_self_forwards = 0.0;
   _cur_string_dedup_fixup_time_ms = 0.0;
+  _cur_prepare_tlab_time_ms = 0.0;
+  _cur_resize_tlab_time_ms = 0.0;
+  _cur_derived_pointer_table_update_time_ms = 0.0;
   _cur_clear_ct_time_ms = 0.0;
   _cur_expand_heap_time_ms = 0.0;
   _cur_ref_proc_time_ms = 0.0;
@@ -125,6 +128,7 @@
   _recorded_redirty_logged_cards_time_ms = 0.0;
   _recorded_preserve_cm_referents_time_ms = 0.0;
   _recorded_merge_pss_time_ms = 0.0;
+  _recorded_start_new_cset_time_ms = 0.0;
   _recorded_total_free_cset_time_ms = 0.0;
   _recorded_serial_free_cset_time_ms = 0.0;
   _cur_fast_reclaim_humongous_time_ms = 0.0;
@@ -288,6 +292,7 @@
   if (_root_region_scan_wait_time_ms > 0.0) {
     debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
   }
+  debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
   debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
   if (G1EagerReclaimHumongousObjects) {
     debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
@@ -375,6 +380,9 @@
   debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
 
   debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
+#if defined(COMPILER2) || INCLUDE_JVMCI
+  debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms);
+#endif
   if (_recorded_clear_claimed_marks_time_ms > 0.0) {
     debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
   }
@@ -390,6 +398,10 @@
     debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
     trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
   }
+  debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
+  if (UseTLAB && ResizeTLAB) {
+    debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
+  }
   debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
 
 

--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp	Wed Mar 15 10:25:37 2017 -0400
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp	Thu Mar 16 09:05:20 2017 +0100
@@ -97,6 +97,11 @@
 
   double _cur_string_dedup_fixup_time_ms;
 
+  double _cur_prepare_tlab_time_ms;
+  double _cur_resize_tlab_time_ms;
+
+  double _cur_derived_pointer_table_update_time_ms;
+
   double _cur_clear_ct_time_ms;
   double _cur_expand_heap_time_ms;
   double _cur_ref_proc_time_ms;
@@ -118,6 +123,8 @@
 
   double _recorded_merge_pss_time_ms;
 
+  double _recorded_start_new_cset_time_ms;
+
   double _recorded_total_free_cset_time_ms;
 
   double _recorded_serial_free_cset_time_ms;
@@ -172,6 +179,18 @@
 
  public:
 
+  void record_prepare_tlab_time_ms(double ms) {
+    _cur_prepare_tlab_time_ms = ms;
+  }
+
+  void record_resize_tlab_time_ms(double ms) {
+    _cur_resize_tlab_time_ms = ms;
+  }
+
+  void record_derived_pointer_table_update_time(double ms) {
+    _cur_derived_pointer_table_update_time_ms = ms;
+  }
+
   void record_clear_ct_time(double ms) {
     _cur_clear_ct_time_ms = ms;
   }
@@ -259,6 +278,10 @@
     _recorded_merge_pss_time_ms = time_ms;
   }
 
+  void record_start_new_cset_time_ms(double time_ms) {
+    _recorded_start_new_cset_time_ms = time_ms;
+  }
+
   void record_cur_collection_start_sec(double time_ms) {
     _cur_collection_start_sec = time_ms;
   }

--- a/hotspot/test/gc/g1/TestGCLogMessages.java	Wed Mar 15 10:25:37 2017 -0400
+++ b/hotspot/test/gc/g1/TestGCLogMessages.java	Thu Mar 16 09:05:20 2017 +0100
@@ -115,6 +115,12 @@
         new LogMessageWithLevel("Preserve CM Refs", Level.DEBUG),
         // Merge PSS
         new LogMessageWithLevel("Merge Per-Thread State", Level.DEBUG),
+        // TLAB handling
+        new LogMessageWithLevel("Prepare TLABs", Level.DEBUG),
+        new LogMessageWithLevel("Resize TLABs", Level.DEBUG),
+
+        new LogMessageWithLevel("DerivedPointerTable Update", Level.DEBUG),
+        new LogMessageWithLevel("Start New Collection Set", Level.DEBUG),
     };
 
     void checkMessagesAtLevel(OutputAnalyzer output, LogMessageWithLevel messages[], Level level) throws Exception {