When it comes to method time-consuming statistics, performance debugging, etc., development often do, but we are in the process of doing this thing, it seems that many people are using a very violent way to do. Where you need to count the time, use the timestamp variable directly and calculate the result at the end, as in the following example:
private static void work(a) {
long time1 = System.currentTimeMillis();
workA();
long time2 = System.currentTimeMillis();
workB();
long time3 = System.currentTimeMillis();
workC();
long time4 = System.currentTimeMillis();
workEnd();
long time5 = System.currentTimeMillis();
long aRunTime = time2 - time1;
long bRunTime = time3 - time2;
long cRunTime = time4 - time3;
long totalRunTime = time5 - time1;
// Collect statistics on the time and total time of A, B, and C
System.out.println("aRunTime:" + aRunTime + " bRunTime:" + bRunTime + " cRunTime:" + cRunTime + " totalRunTime:" + totalRunTime);
}
Copy the codeDoes that ring a bell? This practice our colleagues are often dry, ha ha ha, simple write two graphs save trouble, but often not save trouble ~ alas.
We can write local variable statistics in a method, we can write member variable statistics in multiple methods, not in the same class, page jumps and so on? Write a few global static variables to count?
I personally do not like this way of writing, feeling that it will be more and more messy, and become very troublesome, complex, and difficult to control and view, so finally write a simple and convenient small tool.
The effect picture is as follows:
Explain a wave
- The first line contains the label, indicating the start.
- The last line collects statistics on the total time and the number of times that records are added, indicating the end.
- The middle section is the specific record each time. Example: 1492 ms message: Run A.
- 1492 ms (ms) is the time taken relative to the previous record.
- The “Execute A” in “Message: Execute A” is an arbitrary message content.
- The execution time of task A is 1492 ms, and that of task B is 0 ms (the time is too small to be calculated in milliseconds).
- The time between any two records can be added to obtain the interval time, for example, the time from the start to task C = 1492 + 2004 = 3496ms.
Code implementation
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.ConcurrentHashMap;
/** * a utility class to help record the time spent in method calls. * * <pre> * TimingRecorder. AddRecord (label, "work"); * / /... do some work A ... * TimingRecorder.addRecord(label, "work A"); * / /... do some work B ... * TimingRecorder.addRecord(label, "work B"); * / /... do some work C ... * TimingRecorder.addRecord(label, "work C"); * TimingRecorder.logTime(label); * </pre> * * <p>logTime An example of output after the call is as follows :</p> * * <pre> * Label: label < Start > * 0 MS message: Start * 1501 MS message: A * 302 ms message: B * 2002 ms message: completed ~ * < End > Total time: 3805 ms Number of records: 4 * </pre> * *@author LiuFeng
* @dateThe 2020-10-21 * /
public class TimingRecorder {
private static String TAG = "TimingRecorder";
// Whether to call print
private static boolean isToLog = true;
// The maximum number of records that can be added to a single label
private static final int RECORD_MAX_NUM = 1000;
// Record the storage container
private static final ConcurrentHashMap<String, List<RecordTime>> recordMap = new ConcurrentHashMap<>();
/** * Add record **@paramLabel Indicates the label * of the record@paramMessage Indicates the content of a log. * /
public static void addRecord(String label, String message) {
// Time record
RecordTime recordTime = new RecordTime();
/ / Android can use SystemClock. ElapsedRealtime ()
// Instead of system.nanotime () / 1000_000, the same effect is taken into account in Java
recordTime.time = System.nanoTime() / 1000 _000;
recordTime.message = message;
// Process the store record
handleRecordTimes(label, recordTime);
}
/** * Process record data set (too much data will be released) **@param label
* @param recordTime
*/
private static synchronized void handleRecordTimes(String label, RecordTime recordTime) {
// Retrieve the record
List<RecordTime> recordTimes = getRecordTimes(label);
// When the record capacity is exceeded, print release is called to avoid too much memory for unprinted records
if (recordTimes.size() >= RECORD_MAX_NUM) {
String desc = label + ": Add too many records! will invoke logTime.";
println(desc);
// The first item is reserved to release the time calculated from the first item after printing
RecordTime firstRecordTime = recordTimes.get(0);
// Perform print records and clear labels
logTime(label, desc);
// Store the first data to the new container
recordTimes = getRecordTimes(label);
recordTimes.add(firstRecordTime);
}
// Store a new record
recordTimes.add(recordTime);
}
/** * get the label corresponding container **@param label
* @return* /
private static List<RecordTime> getRecordTimes(String label) {
List<RecordTime> recordTimes = recordMap.get(label);
// Create a container
if (recordTimes == null) {
recordTimes = new ArrayList<>();
List<RecordTime> tempRecords = recordMap.putIfAbsent(label, recordTimes);
if(tempRecords ! =null) { recordTimes = tempRecords; }}return recordTimes;
}
/** * Print record time **@paramLabel Indicates the label * of the record@return* /
public static String logTime(String label) {
return logTime(label, null);
}
/** * Print record time **@paramLabel Indicates the label * of the record@paramMSG Indicates the added log content. *@return* /
public static String logTime(String label, String msg) {
List<RecordTime> recordTimes;
// Locking ensures the security of adding and removing data
synchronized (TimingRecorder.class) {
// Remove the mark
recordTimes = recordMap.remove(label);
}
// Add an end record to the record capacity
if(recordTimes ! =null && recordTimes.size() < RECORD_MAX_NUM) {
RecordTime recordTime = new RecordTime();
recordTime.time = System.nanoTime() / 1000 _000; recordTime.message = msg ! =null ? msg : "log time end.";
recordTimes.add(recordTime);
}
// Parse the record
String record = parseRecord(label, recordTimes);
/ / print
if (isToLog) {
println(record);
}
return record;
}
/** * parse record data **@param label
* @param recordTimes
* @return* /
private static String parseRecord(String label, List<RecordTime> recordTimes) {
// Assemble data
StringBuilder buffer = new StringBuilder();
buffer.append("\n tag:").append(label);
// No record processing
if (recordTimes == null || recordTimes.isEmpty()) {
buffer.append("< no record >");
return buffer.toString();
}
buffer.append("< start >\n");
int size = recordTimes.size();
// Record time for the first time
long firstTime = recordTimes.get(0).time;
// Record the last time
long lastTime = recordTimes.get(size - 1).time;
/ / total time
long totalTime = lastTime - firstTime;
// Calculate the previous time of the elapsed time
long prevTime = firstTime;
// Take the total number of bits, denoted as the maximum bit length, used for space indentation
int maxDigitLength = String.valueOf(totalTime).length();
// Calculate the difference and splice the data
for (int i = 0; i < size; i++) {
RecordTime record = recordTimes.get(i);
long spaceTime = record.time - prevTime;
prevTime = record.time;
// The current time bit is long
int currentDigitLength = String.valueOf(spaceTime).length();
// Indent space characters (for easy alignment)
String indentSpaceStr = getSpaceStr(maxDigitLength - currentDigitLength);
/ / stitching
buffer.append(indentSpaceStr);
buffer.append(spaceTime).append(" ms");
buffer.append(" message: ").append(record.message);
buffer.append("\n");
}
buffer.append(End of the "< >");
buffer.append("Total time:").append(totalTime).append(" ms");
buffer.append("Number of records:").append(size).append("Time");
return buffer.toString();
}
/** * Model */
private static class RecordTime {
long time;
String message;
}
/** * generates a specified number of space strings **@param spaces
* @return* /
private static String getSpaceStr(int spaces) {
String number = String.valueOf(spaces <= 0 ? "" : spaces);
return String.format("%" + number + "s"."");
}
/** * Call log print **@param msg
*/
private static void println(String msg) {
// Use system. out in Java and Log in Android
System.out.println(msg);
//Log.println(Log.INFO, TAG, msg);}}Copy the codeuse
// Before executing the task, call addRecord to add a record
TimingRecorder.addRecord("label"."work start");
// ... do some work A ...
TimingRecorder.addRecord("label"."work A");
// ... do some work B ...
TimingRecorder.addRecord("label"."work B");
// ... do some work C ...
TimingRecorder.addRecord("label"."work C");
// Call logTime to print time statistics
TimingRecorder.logTime("label"."work end");
Copy the codeTo achieve?
- Simple, easy to use, do not manually write the timestamp to calculate it.
- You can count a lot of method function time, want to count a few write a few.
- Label as the only key to distinguish different statistical time, easy to understand, can be across different methods, different classes to add records.
- One statistic is recorded in one log, which is nice to look at without having to look around for other records.
Matters needing attention
- IsToLog controls the log printing switch. If the official environment does not need to print logs, set false to disable it.
- The logTime() method returns a string of statistics records that can be retrieved and thrown into a local file, etc.
- The maximum number of records that can be added to a single label is 1000, but it is not said that if the number exceeds that, it cannot be used. In order to reduce memory usage, it will print the empty release first, and the subsequent statistics can be strung together.
- System.nanotime () / 1000_000 is used to record time in the code, so if you need a more precise time, such as microseconds, divide by 1000.
- Call Log printing: System.out is used in Java, and Log is best used in Android.
The last
Looks simple a small tool, in fact, there are a lot of things to consider, there are also not considered problems, we can modify according to their own needs.