1 /*-
2  * See the file LICENSE for redistribution information.
3  *
4  * Copyright (c) 2002, 2014 Oracle and/or its affiliates.  All rights reserved.
5  *
6  */
7 
8 package com.sleepycat.je.dbi;
9 
10 import java.io.ByteArrayOutputStream;
11 import java.io.PrintStream;
12 import java.util.EnumMap;
13 import java.util.Formatter;
14 import java.util.Map;
15 import java.util.logging.Level;
16 import java.util.logging.Logger;
17 
18 import com.sleepycat.je.EnvironmentFailureException;
19 import com.sleepycat.je.ProgressListener;
20 import com.sleepycat.je.RecoveryProgress;
21 import com.sleepycat.je.config.EnvironmentParams;
22 import com.sleepycat.je.recovery.CheckpointEnd;
23 import com.sleepycat.je.recovery.RecoveryInfo;
24 import com.sleepycat.je.utilint.DbLsn;
25 import com.sleepycat.je.utilint.LoggerUtils;
26 import com.sleepycat.je.utilint.StatGroup;
27 
28 /**
29  * Store and calculate elapsed time, counts, and other statistics about
30  * environment open. No synchronization is used, which generally works because
31  * with the exception of replication, environment startup is currently a
32  * serial, single threaded event. Replicated environments must be sure to
33  * record startup times only at thread safe points.
34  */
35 public class StartupTracker {
36 
37     /*
38      * Statistics are kept about startup phases, defined below. Phases can
39      * be nested, so the child and root fields are used to express this
40      * relationship. For example:
41      *  TotalEnvOpen
42      *      TotalRecovery
43      *         FindEndOfLog
44      *          ..
45      *         BuildTree
46      *             ReadMapIN
47      *             ..
48      *         Ckpt
49      *  TotalJoinGroup encompasses the following two phases.
50      *      FindMaster
51      *      BecomeConsistent
52      * Keep these enums in order of execution, so that the display is easier to
53      * comprehend. Of course, some phases subsume other phases, but in general,
54      * this enum order follows the order of execution.
55      */
56     public enum Phase {
57             TOTAL_ENV_OPEN("Environment Open"),
58             TOTAL_RECOVERY,
59             FIND_END_OF_LOG,
60             FIND_LAST_CKPT,
61             BUILD_TREE,
62             READ_MAP_INS,
63             REDO_MAP_INS,
64             UNDO_MAP_LNS,
65             REDO_MAP_LNS,
66             READ_INS,
67             REDO_INS,
68             UNDO_LNS,
69             REDO_LNS,
70             POPULATE_UP,
71             REMOVE_TEMP_DBS,
72             CKPT,
73             TOTAL_JOIN_GROUP("Replication Join Group"),
74             FIND_MASTER,
75             BECOME_CONSISTENT;
76 
77         private Phase[] children;
78         private Phase root;
79         private String reportLabel;
80 
Phase()81         private Phase() {
82         }
83 
Phase(String reportLabel)84         private Phase(String reportLabel) {
85             this.reportLabel = reportLabel;
86         }
87 
88         static {
89             TOTAL_ENV_OPEN.children = new Phase[]
90                 {TOTAL_RECOVERY};
91             TOTAL_RECOVERY.children = new Phase[]
92                 {FIND_END_OF_LOG,
93                  FIND_LAST_CKPT,
94                  BUILD_TREE,
95                  POPULATE_UP,
96                  REMOVE_TEMP_DBS,
97                  CKPT};
98             BUILD_TREE.children = new Phase[]
99                 {READ_MAP_INS,
100                  REDO_MAP_INS,
101                  UNDO_MAP_LNS,
102                  REDO_MAP_LNS,
103                  READ_INS,
104                  REDO_INS,
105                  UNDO_LNS,
106                  REDO_LNS};
107             TOTAL_JOIN_GROUP.children = new Phase[]
108                 {FIND_MASTER,
109                  BECOME_CONSISTENT};
110 
111             TOTAL_RECOVERY.root = TOTAL_ENV_OPEN;
112             FIND_END_OF_LOG.root = TOTAL_ENV_OPEN;
113             FIND_LAST_CKPT.root = TOTAL_ENV_OPEN;
114             BUILD_TREE.root = TOTAL_ENV_OPEN;
115             READ_MAP_INS.root = TOTAL_ENV_OPEN;
116             REDO_MAP_INS.root = TOTAL_ENV_OPEN;
117             UNDO_MAP_LNS.root = TOTAL_ENV_OPEN;
118             REDO_MAP_LNS.root = TOTAL_ENV_OPEN;
119             READ_INS.root = TOTAL_ENV_OPEN;
120             REDO_INS.root = TOTAL_ENV_OPEN;
121             UNDO_LNS.root = TOTAL_ENV_OPEN;
122             REDO_LNS.root = TOTAL_ENV_OPEN;
123             POPULATE_UP.root = TOTAL_ENV_OPEN;
124             REMOVE_TEMP_DBS.root = TOTAL_ENV_OPEN;
125             CKPT.root = TOTAL_ENV_OPEN;
126 
127             FIND_MASTER.root = TOTAL_JOIN_GROUP;
128             BECOME_CONSISTENT.root = TOTAL_JOIN_GROUP;
129         }
130     }
131 
132     private final Map<Phase, Elapsed> elapsed;
133     private final Map<Phase, Counter> counters;
134     private final Map<Phase, StatGroup> stats;
135     private final Logger logger;
136     private final EnvironmentImpl envImpl;
137     private RecoveryInfo info;
138     private long lastDumpMillis;
139 
StartupTracker(EnvironmentImpl envImpl)140     public StartupTracker(EnvironmentImpl envImpl) {
141 
142         elapsed = new EnumMap<Phase, Elapsed>(Phase.class);
143         counters = new EnumMap<Phase, Counter>(Phase.class);
144         stats = new EnumMap<Phase, StatGroup>(Phase.class);
145         for (Phase p : Phase.values()){
146             elapsed.put(p, new Elapsed());
147         }
148 
149         this.envImpl = envImpl;
150 
151         logger = LoggerUtils.getLogger(getClass());
152         lastDumpMillis = System.currentTimeMillis();
153     }
154 
setRecoveryInfo(RecoveryInfo rInfo)155     public void setRecoveryInfo(RecoveryInfo rInfo) {
156         info = rInfo;
157     }
158 
159     /**
160      * Note that a particular phase is starting.
161      */
start(Phase phase)162     public void start(Phase phase) {
163         String msg = "Starting " + phase;
164         if (info != null) {
165             msg += " " + info;
166         }
167         LoggerUtils.logMsg(logger, envImpl, Level.CONFIG, msg);
168 
169         elapsed.get(phase).start();
170         Counter c = new Counter();
171         counters.put(phase, c);
172         if (!phase.equals(Phase.TOTAL_ENV_OPEN)) {
173 
174             /*
175              * LogManager does not exist yet so we can't reference it. Anyway,
176              * cache misses are 0 to start with, so TOTAL_ENV_OPEN does not
177              * have to set the starting cache miss count.
178              */
179             c.setCacheMissStart(envImpl.getLogManager().getNCacheMiss());
180         }
181     }
182 
183     /**
184      * Note that a particular phase is ending.
185      */
stop(Phase phase)186     public void stop(Phase phase) {
187         Elapsed e = elapsed.get(phase);
188         e.end();
189         Counter c = getCounter(phase);
190         c.setCacheMissEnd(envImpl.getLogManager().getNCacheMiss());
191 
192         /* Log this phase to the je.info file. */
193         String msg = "Stopping " + phase;
194         if (info != null) {
195             msg += " " + info;
196         }
197         LoggerUtils.logMsg(logger, envImpl, Level.CONFIG, msg);
198 
199         /*
200          * Conditionally log the whole report to the je.info file, either
201          * because this family of phases has ended, or because this startup
202          * is taking a very long time.
203          *
204          * Take care to only check the value of dumpThreshold here, rather than
205          * setting it in the StartupTracker constructor, because StartupTracker
206          * is instantiated before the DbConfigManager and the
207          * STARTUP_DUMP_THRESHOLD param cannot be read.
208          */
209         int dumpThreshold = envImpl.getConfigManager().getDuration
210             (EnvironmentParams.STARTUP_DUMP_THRESHOLD);
211 
212         /* We're at the end of a family of phases. */
213         if (phase.root == null) {
214             if ((e.getEnd() - e.getStart()) > dumpThreshold) {
215                 ByteArrayOutputStream baos = new ByteArrayOutputStream();
216                 PrintStream p = new PrintStream(baos);
217                 displayStats(p, phase);
218                 LoggerUtils.logMsg(logger, envImpl, Level.INFO,
219                                    baos.toString());
220                 return;
221             }
222         }
223 
224         /*
225          * It's not the ending phase, but this has been taking a very long
226          * time, so dump some information.
227          */
228          if ((System.currentTimeMillis() - lastDumpMillis) > dumpThreshold) {
229              ByteArrayOutputStream baos = new ByteArrayOutputStream();
230              PrintStream p = new PrintStream(baos);
231              displayInterim(p, phase);
232              LoggerUtils.logMsg(logger, envImpl, Level.INFO, baos.toString());
233          }
234     }
235 
236     /**
237      * Record new progress states for any registered environment progress
238      * listener.
239      */
setProgress(RecoveryProgress progress)240     public void setProgress(RecoveryProgress progress) {
241         ProgressListener<RecoveryProgress> progressListener =
242             envImpl.getRecoveryProgressListener();
243 
244         if (progressListener == null) {
245             return;
246         }
247         if (!progressListener.progress(progress, -1, -1)) {
248             throw new EnvironmentFailureException
249               (envImpl, EnvironmentFailureReason.PROGRESS_LISTENER_HALT,
250               "EnvironmentConfig.recoveryProgressListener: ");
251         }
252     }
253 
254     /**
255      * Return the counter for this phase so we can update one of the detail
256      * values stored there.
257      */
getCounter(Phase phase)258     public Counter getCounter(Phase phase) {
259         return counters.get(phase);
260     }
261 
262     /**
263      * Save stats for a given phase.
264      */
setStats(Phase phase, StatGroup sg)265     public void setStats(Phase phase, StatGroup sg) {
266         stats.put(phase, sg);
267     }
268 
269     /**
270      * Generate a description of the four recovery locations (firstActive,
271      * ckptStart, ckptend, end of Log) and the distance inbetween.
272      */
displayRecoveryInterval()273     private String displayRecoveryInterval() {
274         StringBuilder returnInfo = new StringBuilder();
275 
276         CheckpointEnd cEnd = info.checkpointEnd;
277         if (cEnd != null) {
278             returnInfo.append("checkpointId = ");
279             returnInfo.append(cEnd.getId());
280             if (cEnd.getInvoker() == null) {
281                 returnInfo.append(" ");
282             } else {
283                 returnInfo.append("[").append(cEnd.getInvoker());
284                 returnInfo.append("] ");
285             }
286         }
287 
288         long fileMax =
289             envImpl.getConfigManager().getLong(EnvironmentParams.LOG_FILE_MAX);
290 
291         long useStart = info.checkpointStartLsn == DbLsn.NULL_LSN ?
292             0 : info.checkpointStartLsn;
293         long head = DbLsn.getNoCleaningDistance(useStart,
294                                                 info.firstActiveLsn,
295                                                 fileMax);
296 
297         long useEnd = info.checkpointEndLsn == DbLsn.NULL_LSN ?
298             0 : info.checkpointEndLsn;
299         long ckpt = DbLsn.getNoCleaningDistance(useEnd,
300                                                 info.checkpointStartLsn,
301                                                 fileMax);
302 
303         long useLast = info.lastUsedLsn == DbLsn.NULL_LSN ?
304             0 : info.lastUsedLsn;
305         long tail = DbLsn.getNoCleaningDistance(useLast,
306                                                 info.checkpointEndLsn,
307                                                 fileMax);
308         returnInfo.append(
309             "firstActive[" +
310             DbLsn.getNoFormatString(info.firstActiveLsn) +
311             "], ckptStart[" +
312             DbLsn.getNoFormatString(info.checkpointStartLsn) +
313             "], ckptEnd[" +
314             DbLsn.getNoFormatString(info.checkpointEndLsn) +
315             "], lastUsed[" +
316             DbLsn.getNoFormatString(info.lastUsedLsn) +
317             "]\n");
318         StringBuilder sb = new StringBuilder();
319         Formatter f = new Formatter(sb);
320         f.format("%24s bytes = %,d\n%24s bytes = %,d\n%24s bytes = %,d",
321                  "firstActive->ckptStart", head,
322                  "ckptStart->ckptEnd", ckpt,
323                  "ckptEnd->end bytes", tail);
324 
325         return returnInfo.toString() + "\nApproximate distances:\n" +
326             sb.toString();
327     }
328 
displayTimestamp(Long time)329     private String displayTimestamp(Long time) {
330         StringBuilder sb = new StringBuilder();
331         Formatter timestampFormatter = new Formatter(sb);
332         timestampFormatter.format("%tD,%tH:%tM:%tS:%tL",
333                                   time, time, time, time, time);
334         return sb.toString();
335     }
336 
337     /**
338      * Display a phase and its children, showing elapsed time as a
339      * percentage of the phases' root.
340      */
displayPhaseSubtree(PrintStream stream, Phase parent, Elapsed parentTime, Elapsed rootElapsed)341     private void displayPhaseSubtree(PrintStream stream,
342                                      Phase parent,
343                                      Elapsed parentTime,
344                                      Elapsed rootElapsed) {
345 
346         String headerFormat = "%24s  %% of total  %s\n";
347         String parentFormat = "%20s             %3d %s\n";
348         String dataFormat   = "%24s         %3d %s\n";
349         String divider = "                         "+
350             "-------------------------";
351 
352         if (parent.children == null) {
353             return;
354         }
355 
356         if ((parentTime.getEnd() - parentTime.getStart()) ==0) {
357             return;
358         }
359 
360         stream.println("\n");
361         stream.printf(headerFormat, " ", Elapsed.DISPLAY_COLUMNS);
362         stream.printf(parentFormat, parent,
363                       parentTime.getPercentage(rootElapsed), parentTime);
364         stream.println(divider);
365 
366         for (Phase child : parent.children) {
367             Elapsed time = elapsed.get(child);
368             if (time.getStart() == 0) {
369                 continue;
370             }
371             stream.printf(dataFormat,
372                           child,
373                           time.getPercentage(rootElapsed),
374                           time);
375         }
376     }
377 
displayCounters(PrintStream stream, Phase root)378     private void displayCounters(PrintStream stream, Phase root) {
379         String basicFormat = "%20s   %s\n";
380         boolean headerNotPrinted = true;
381         for (Map.Entry<Phase, Counter> c : counters.entrySet()) {
382             Phase p = c.getKey();
383             if (p.root != root) {
384                 continue;
385             }
386             Counter counter = c.getValue();
387             if (counter.isEmpty()) {
388                 continue;
389             }
390 
391             if (headerNotPrinted) {
392                 stream.println();
393                 stream.printf(basicFormat, " " , Counter.DISPLAY_COLUMNS);
394                 headerNotPrinted = false;
395             }
396             stream.printf(basicFormat, c.getKey(), counter);
397         }
398     }
399 
400     /**
401      * Display all information that has been tracked for this family of
402      * phases.
403      */
displayStats(PrintStream stream, Phase root )404     public void displayStats(PrintStream stream, Phase root ) {
405         lastDumpMillis = System.currentTimeMillis();
406         Elapsed rootTime = elapsed.get(root);
407 
408         stream.println("\n=== " + root.reportLabel + " Report  ===");
409         stream.println("start = " + displayTimestamp(rootTime.getStart()));
410         stream.println("end   = " + displayTimestamp(rootTime.getEnd()));
411         if (root == Phase.TOTAL_ENV_OPEN) {
412             stream.print(displayRecoveryInterval());
413         }
414 
415         /* Elapsed time. */
416         for (Map.Entry<Phase, Elapsed> x : elapsed.entrySet()) {
417             Phase p = x.getKey();
418             if (p.root == null) {
419                if (p != root) {
420                    continue;
421                }
422             } else if (p.root != root) {
423                continue;
424             }
425 
426             displayPhaseSubtree(stream, x.getKey(),x.getValue(), rootTime);
427         }
428 
429         /* Counters */
430         displayCounters(stream, root);
431 
432         /* Stats */
433         for (Map.Entry<Phase, StatGroup> s : stats.entrySet()) {
434             Phase p = s.getKey();
435             if (p.root != root) {
436                 continue;
437             }
438             stream.println(s.getKey() + " stats:");
439             stream.println(s.getValue());
440         }
441     }
442 
443     /**
444      * Display all information available so far.
445      */
displayInterim(PrintStream stream, Phase phase )446     private void displayInterim(PrintStream stream, Phase phase ) {
447         lastDumpMillis = System.currentTimeMillis();
448 
449         stream.println("\n=== Interim " + phase + " Report  ===");
450 
451         stream.println(displayRecoveryInterval());
452 
453         /* Elapsed time. */
454         boolean headerNotPrinted = true;
455         for (Map.Entry<Phase, Elapsed> x : elapsed.entrySet()) {
456             Phase p = x.getKey();
457             Elapsed e = x.getValue();
458             if (e.start == 0) {
459                 continue;
460             }
461             if (headerNotPrinted) {
462                 stream.println("                             Elapsed(ms)");
463                 headerNotPrinted = false;
464             }
465             stream.printf("%20s : %s\n", p, e);
466         }
467 
468         /* Counters */
469         displayCounters(stream, phase.root);
470 
471         /* Stats */
472         for (Map.Entry<Phase, StatGroup> s : stats.entrySet()) {
473             stream.println(s.getKey() + " stats:");
474             stream.println(s.getValue());
475         }
476     }
477 
478     /** Measures elapsed time in millisecond granularity. */
479     static private class Elapsed {
480 
481         /* For dumping elapsed values in a column */
482         static String DISPLAY_COLUMNS = " Elapsed(ms)";
483 
484         private long start;
485         private long end;
486 
getStart()487         public long getStart() {
488             return start;
489         }
490 
getEnd()491         public long getEnd() {
492             return end;
493         }
494 
495         /* Mark the start of a phase. */
start()496         private void start() {
497             start = System.currentTimeMillis();
498         }
499 
500         /* Mark the end of a phase. */
end()501         private void end() {
502             end = System.currentTimeMillis();
503         }
504 
getPercentage(Elapsed rootTime)505         private int getPercentage(Elapsed rootTime) {
506             if (rootTime == null) {
507                 return 0;
508             }
509 
510             long rootTotal = rootTime.end-rootTime.start;
511             if (rootTotal <= 0) {
512                 return 0;
513             }
514 
515             if (end == 0) {
516                 return 0;
517             }
518             return (int)(((float) (end-start)/ rootTotal) * 100);
519         }
520 
521         @Override
toString()522         public String toString() {
523             StringBuilder sb = new StringBuilder();
524             Formatter f = new Formatter(sb);
525             if (end != 0) {
526                 f.format("%,13d", (end-start));
527             } else {
528                 if (start != 0) {
529                     f.format("%13s  %tD,%tH:%tM:%tS:%tL",
530                              "started at", start, start, start, start, start);
531                 } else {
532                     f.format("%13s", "none");
533                 }
534             }
535             return sb.toString();
536         }
537     }
538 
539     /**
540      * Record number of log entries processed during a given recovery phase.
541      */
542     static public class Counter {
543         private int numRead;
544         private int numProcessed;
545         private int numDeleted;
546         private int numAux;
547         private long numRepeatIteratorReads;
548         private long startCacheMiss;
549         private long endCacheMiss;
550 
551         /* If nothing is set, don't print this one. */
isEmpty()552         private boolean isEmpty() {
553             return((numRead==0) &&
554                    (numProcessed==0) &&
555                    (numDeleted==0) &&
556                    (numAux==0) &&
557                    (numRepeatIteratorReads==0) &&
558                    ((endCacheMiss-startCacheMiss)==0));
559         }
560 
incNumRead()561         public void incNumRead() {
562             numRead++;
563         }
564 
incNumProcessed()565         public void incNumProcessed() {
566             numProcessed++;
567         }
568 
incNumDeleted()569         public void incNumDeleted() {
570             numDeleted++;
571         }
572 
573         /**
574          * Keep track of auxiliary log entries processed during this pass.
575          * For example, LNs are the main target of the undoLN pass, but we
576          * also read aborts and commits.
577          */
incNumAux()578         public void incNumAux() {
579             numAux++;
580         }
581 
setRepeatIteratorReads(long repeats)582         public void setRepeatIteratorReads(long repeats) {
583             numRepeatIteratorReads = repeats;
584         }
585 
setCacheMissStart(long miss)586         public void setCacheMissStart(long miss) {
587             startCacheMiss = miss;
588         }
589 
setCacheMissEnd(long miss)590         public void setCacheMissEnd(long miss) {
591             endCacheMiss = miss;
592         }
593 
594         static String DISPLAY_COLUMNS =
595 "      nRead nProcessed   nDeleted       nAux  nRepeatRd nCacheMiss";
596 
597         @Override
toString()598         public String toString() {
599             StringBuilder sb = new StringBuilder();
600             Formatter f = new Formatter(sb);
601             f.format("%,11d%,11d%,11d%,11d%,11d%,11d",
602                      numRead, numProcessed, numDeleted, numAux,
603                      numRepeatIteratorReads, (endCacheMiss - startCacheMiss));
604             return sb.toString();
605         }
606 
getNumProcessed()607         public int getNumProcessed() {
608             return numProcessed;
609         }
610     }
611 }
612