View Javadoc
1   /*
2    * Copyright 2021 TiKV Project Authors.
3    *
4    * Licensed under the Apache License, Version 2.0 (the "License");
5    * you may not use this file except in compliance with the License.
6    * You may obtain a copy of the License at
7    *
8    * http://www.apache.org/licenses/LICENSE-2.0
9    *
10   * Unless required by applicable law or agreed to in writing, software
11   * distributed under the License is distributed on an "AS IS" BASIS,
12   * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13   * See the License for the specific language governing permissions and
14   * limitations under the License.
15   *
16   */
17  
18  package org.tikv.common.log;
19  
20  import com.google.gson.JsonArray;
21  import com.google.gson.JsonObject;
22  import java.math.BigInteger;
23  import java.text.SimpleDateFormat;
24  import java.util.ArrayList;
25  import java.util.HashMap;
26  import java.util.List;
27  import java.util.Map;
28  import java.util.Map.Entry;
29  import java.util.Random;
30  import org.slf4j.Logger;
31  import org.slf4j.LoggerFactory;
32  
33  public class SlowLogImpl implements SlowLog {
34  
35    private static final Logger logger = LoggerFactory.getLogger(SlowLogImpl.class);
36  
37    private static final int MAX_SPAN_SIZE = 1024;
38  
39    private static final Random random = new Random();
40  
41    private final List<SlowLogSpan> slowLogSpans = new ArrayList<>();
42    private final HashMap<String, Object> fields = new HashMap<>();
43    private Throwable error = null;
44  
45    private final long startMS;
46    /**
47     * use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic
48     */
49    private final long startNS;
50  
51    private final long slowThresholdMS;
52  
53    private final long traceId;
54  
55    private long durationMS;
56  
57    public SlowLogImpl(long slowThresholdMS) {
58      this.startMS = System.currentTimeMillis();
59      this.startNS = System.nanoTime();
60      this.slowThresholdMS = slowThresholdMS;
61      this.traceId = random.nextLong();
62    }
63  
64    @Override
65    public synchronized SlowLogSpan start(String name) {
66      SlowLogSpan slowLogSpan = new SlowLogSpanImpl(name, startMS, startNS);
67      if (slowLogSpans.size() < MAX_SPAN_SIZE) {
68        slowLogSpans.add(slowLogSpan);
69      }
70      slowLogSpan.start();
71      return slowLogSpan;
72    }
73  
74    @Override
75    public long getTraceId() {
76      return traceId;
77    }
78  
79    @Override
80    public long getThresholdMS() {
81      return slowThresholdMS;
82    }
83  
84    @Override
85    public void setError(Throwable err) {
86      this.error = err;
87    }
88  
89    @Override
90    public SlowLog withFields(Map<String, Object> fields) {
91      this.fields.putAll(fields);
92      return this;
93    }
94  
95    @Override
96    public Object getField(String key) {
97      return fields.get(key);
98    }
99  
100   @Override
101   public void log() {
102     recordTime();
103     if (error != null || timeExceeded()) {
104       SimpleDateFormat dateFormat = new SimpleDateFormat("HH:mm:ss.SSS");
105       logger.warn(
106           String.format(
107               "A request spent %s ms. start=%s, end=%s, SlowLog:%s",
108               durationMS,
109               dateFormat.format(startMS),
110               dateFormat.format(startMS + durationMS),
111               getSlowLogJson().toString()));
112     }
113   }
114 
115   private void recordTime() {
116     long currentNS = System.nanoTime();
117     durationMS = (currentNS - startNS) / 1_000_000;
118   }
119 
120   boolean timeExceeded() {
121     return slowThresholdMS >= 0 && durationMS > slowThresholdMS;
122   }
123 
124   JsonObject getSlowLogJson() {
125     JsonObject jsonObject = new JsonObject();
126 
127     jsonObject.addProperty("trace_id", toUnsignedBigInteger(traceId));
128 
129     if (error != null) {
130       jsonObject.addProperty("error", error.getMessage());
131     }
132 
133     JsonArray jsonArray = new JsonArray();
134     for (SlowLogSpan slowLogSpan : slowLogSpans) {
135       jsonArray.add(slowLogSpan.toJsonElement());
136     }
137     jsonObject.add("spans", jsonArray);
138 
139     for (Entry<String, Object> entry : fields.entrySet()) {
140       Object value = entry.getValue();
141       if (value instanceof List) {
142         JsonArray field = new JsonArray();
143         for (Object o : (List<?>) value) {
144           field.add(o.toString());
145         }
146         jsonObject.add(entry.getKey(), field);
147       } else if (value instanceof Map) {
148         JsonObject field = new JsonObject();
149         for (Entry<?, ?> e : ((Map<?, ?>) value).entrySet()) {
150           field.addProperty(e.getKey().toString(), e.getValue().toString());
151         }
152         jsonObject.add(entry.getKey(), field);
153       } else {
154         jsonObject.addProperty(entry.getKey(), value.toString());
155       }
156     }
157 
158     return jsonObject;
159   }
160 
161   static BigInteger toUnsignedBigInteger(long i) {
162     if (i >= 0) {
163       return BigInteger.valueOf(i);
164     } else {
165       long withoutSign = i & ~(1L << 63);
166 
167       return (BigInteger.valueOf(1)).shiftLeft(63).add(BigInteger.valueOf(withoutSign));
168     }
169   }
170 }