Skip to content

Commit bb58a25

Browse files
TommyLemonTommyLemon
committed
调试时间字段新增 parse 和 sql 两个时长，例如 "time:start|duration|end|parse|sql": "1641751048573|145|1641751048718|50|95"
1 parent d41f2a4 commit bb58a25

File tree

4 files changed

+130
-24
lines changed

4 files changed

+130
-24
lines changed

‎APIJSONORM/src/main/java/apijson/Log.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@ public class Log {
1414

1515
public static boolean DEBUG = true;
1616

17-
public static final String VERSION = "4.8.0";
17+
public static final String VERSION = "4.8.5";
1818
public static final String KEY_SYSTEM_INFO_DIVIDER = "---|-----APIJSON SYSTEM INFO-----|---";
1919

2020
//默认的时间格式

‎APIJSONORM/src/main/java/apijson/orm/AbstractParser.java‎

Lines changed: 11 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -353,6 +353,7 @@ public JSONObject parseResponse(String request) {
353353
}
354354

355355
private int queryDepth;
356+
private long executedSQLDuration;
356357

357358
/**解析请求json并获取对应结果
358359
* @param request
@@ -420,6 +421,8 @@ public JSONObject parseResponse(JSONObject request) {
420421
onBegin();
421422
try {
422423
queryDepth = 0;
424+
executedSQLDuration = 0;
425+
423426
requestObject = onObjectParse(request, null, null, null, false);
424427

425428
onCommit();
@@ -441,7 +444,10 @@ public JSONObject parseResponse(JSONObject request) {
441444
if (Log.DEBUG) {
442445
requestObject.put("sql:generate|cache|execute|maxExecute", getSQLExecutor().getGeneratedSQLCount() + "|" + getSQLExecutor().getCachedSQLCount() + "|" + getSQLExecutor().getExecutedSQLCount() + "|" + getMaxSQLCount());
443446
requestObject.put("depth:count|max", queryDepth + "|" + getMaxQueryDepth());
444-
requestObject.put("time:start|duration|end", startTime + "|" + duration + "|" + endTime);
447+
448+
executedSQLDuration += sqlExecutor.getExecutedSQLDuration() + sqlExecutor.getSqlResultDuration();
449+
long parseDuration = duration - executedSQLDuration;
450+
requestObject.put("time:start|duration|end|parse|sql", startTime + "|" + duration + "|" + endTime + "|" + parseDuration + "|" + executedSQLDuration);
445451

446452
if (error != null) {
447453
requestObject.put("trace:throw", error.getClass().getName());
@@ -1845,7 +1851,10 @@ public JSONObject executeSQL(SQLConfig config, boolean isSubquery) throws Except
18451851
}
18461852
}
18471853
else {
1848-
result = getSQLExecutor().execute(config, false);
1854+
sqlExecutor = getSQLExecutor();
1855+
result = sqlExecutor.execute(config, false);
1856+
// FIXME 改为直接在 sqlExecutor 内加好，最后 Parser 取结果，可以解决并发执行导致内部计算出错
1857+
// executedSQLDuration += sqlExecutor.getExecutedSQLDuration() + sqlExecutor.getSqlResultDuration();
18491858
}
18501859

18511860
return result;

‎APIJSONORM/src/main/java/apijson/orm/AbstractSQLExecutor.java‎

Lines changed: 114 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,6 @@
2525
import java.util.List;
2626
import java.util.Map;
2727
import java.util.Map.Entry;
28-
import java.util.Objects;
2928
import java.util.Set;
3029
import java.util.regex.Pattern;
3130

@@ -37,7 +36,6 @@
3736
import apijson.NotNull;
3837
import apijson.RequestMethod;
3938
import apijson.StringUtil;
40-
import apijson.orm.AbstractSQLConfig;
4139

4240
/**executor for query(read) or update(write) MySQL database
4341
* @author Lemon
@@ -67,6 +65,33 @@ public int getCachedSQLCount() {
6765
public int getExecutedSQLCount() {
6866
return executedSQLCount;
6967
}
68+
69+
// 只要不是并发执行且执行完立刻获取，就不会是错的，否则需要一并返回，可以 JSONObject.put("@EXECUTED_SQL_TIME:START|DURATION|END", )
70+
private long executedSQLStartTime;
71+
private long executedSQLEndTime;
72+
private long executedSQLDuration;
73+
private long sqlResultDuration;
74+
75+
public long getExecutedSQLStartTime() {
76+
return executedSQLStartTime;
77+
}
78+
public long getExecutedSQLEndTime() {
79+
return executedSQLEndTime;
80+
}
81+
@Override
82+
public long getExecutedSQLDuration() {
83+
if (executedSQLDuration <= 0) {
84+
long startTime = getExecutedSQLStartTime();
85+
long endTime = getExecutedSQLEndTime();
86+
executedSQLDuration = startTime <= 0 || endTime <= 0 ? 0 : endTime - startTime; // FIXME 有时莫名其妙地算出来是负数
87+
}
88+
return executedSQLDuration < 0 ? 0 : executedSQLDuration;
89+
}
90+
91+
@Override
92+
public long getSqlResultDuration() {
93+
return sqlResultDuration;
94+
}
7095

7196
/**
7297
* 缓存map
@@ -127,16 +152,25 @@ public JSONObject getCacheItem(String sql, int position, int type) {
127152

128153
@Override
129154
public ResultSet executeQuery(@NotNull Statement statement, String sql) throws Exception {
130-
return statement.executeQuery(sql);
155+
// executedSQLStartTime = System.currentTimeMillis();
156+
ResultSet rs = statement.executeQuery(sql);
157+
// executedSQLEndTime = System.currentTimeMillis();
158+
return rs;
131159
}
132160
@Override
133161
public int executeUpdate(@NotNull Statement statement, String sql) throws Exception {
134-
return statement.executeUpdate(sql);
162+
// executedSQLStartTime = System.currentTimeMillis();
163+
int c = statement.executeUpdate(sql);
164+
// executedSQLEndTime = System.currentTimeMillis();
165+
return c;
135166
}
136167
@Override
137168
public ResultSet execute(@NotNull Statement statement, String sql) throws Exception {
169+
// executedSQLStartTime = System.currentTimeMillis();
138170
statement.execute(sql);
139-
return statement.getResultSet();
171+
ResultSet rs = statement.getResultSet();
172+
// executedSQLEndTime = System.currentTimeMillis();
173+
return rs;
140174
}
141175

142176
/**执行SQL
@@ -146,6 +180,11 @@ public ResultSet execute(@NotNull Statement statement, String sql) throws Except
146180
*/
147181
@Override
148182
public JSONObject execute(@NotNull SQLConfig config, boolean unknowType) throws Exception {
183+
// executedSQLDuration = 0;
184+
executedSQLStartTime = System.currentTimeMillis();
185+
executedSQLEndTime = executedSQLStartTime;
186+
// sqlResultDuration = 0;
187+
149188
boolean isPrepared = config.isPrepared();
150189

151190
final String sql = config.getSQL(false);
@@ -182,15 +221,19 @@ public JSONObject execute(@NotNull SQLConfig config, boolean unknowType) throws
182221

183222
try {
184223
if (unknowType) {
185-
Statement statement = getStatement(config);
186-
187224
if (isExplain == false) { //只有 SELECT 才能 EXPLAIN
188225
executedSQLCount ++;
226+
executedSQLStartTime = System.currentTimeMillis();
189227
}
228+
Statement statement = getStatement(config);
190229
rs = execute(statement, sql);
191-
192-
result = new JSONObject(true);
193230
int updateCount = statement.getUpdateCount();
231+
if (isExplain == false) {
232+
executedSQLEndTime = System.currentTimeMillis();
233+
executedSQLDuration += executedSQLEndTime - executedSQLStartTime;
234+
}
235+
236+
result = new JSONObject(true);
194237
result.put(JSONResponse.KEY_COUNT, updateCount);
195238
result.put("update", updateCount >= 0);
196239
//导致后面 rs.getMetaData() 报错 Operation not allowed after ResultSet closed result.put("moreResults", statement.getMoreResults());
@@ -202,8 +245,14 @@ public JSONObject execute(@NotNull SQLConfig config, boolean unknowType) throws
202245
case DELETE:
203246
if (isExplain == false) { //只有 SELECT 才能 EXPLAIN
204247
executedSQLCount ++;
248+
executedSQLStartTime = System.currentTimeMillis();
205249
}
206250
int updateCount = executeUpdate(config);
251+
if (isExplain == false) {
252+
executedSQLEndTime = System.currentTimeMillis();
253+
executedSQLDuration += executedSQLEndTime - executedSQLStartTime;
254+
}
255+
207256
if (updateCount <= 0) {
208257
throw new IllegalAccessException("没权限访问或对象不存在！"); // NotExistException 会被 catch 转为成功状态
209258
}
@@ -235,8 +284,13 @@ public JSONObject execute(@NotNull SQLConfig config, boolean unknowType) throws
235284

236285
if (isExplain == false) { //只有 SELECT 才能 EXPLAIN
237286
executedSQLCount ++;
287+
executedSQLStartTime = System.currentTimeMillis();
238288
}
239289
rs = executeQuery(config); //FIXME SQL Server 是一次返回两个结果集，包括查询结果和执行计划，需要 moreResults
290+
if (isExplain == false) {
291+
executedSQLEndTime = System.currentTimeMillis();
292+
executedSQLDuration += executedSQLEndTime - executedSQLStartTime;
293+
}
240294
break;
241295

242296
default://OPTIONS, TRACE等
@@ -264,8 +318,10 @@ public JSONObject execute(@NotNull SQLConfig config, boolean unknowType) throws
264318

265319
int index = -1;
266320

321+
long startTime2 = System.currentTimeMillis();
267322
ResultSetMetaData rsmd = rs.getMetaData();
268323
final int length = rsmd.getColumnCount();
324+
sqlResultDuration += System.currentTimeMillis() - startTime2;
269325

270326
//<SELECT * FROM Comment WHERE momentId = '470', { id: 1, content: "csdgs" }>
271327
childMap = new HashMap<>(); //要存到cacheMap
@@ -286,7 +342,14 @@ public JSONObject execute(@NotNull SQLConfig config, boolean unknowType) throws
286342
Join[] columnIndexAndJoinMap = isExplain || ! hasJoin ? null : new Join[length];
287343

288344
// int viceColumnStart = length + 1; //第一个副表字段的index
345+
346+
// FIXME 统计游标查找的时长？可能 ResultSet.next() 及 getTableName, getColumnName, getObject 比较耗时，因为不是一次加载到内存，而是边读边发
347+
348+
long lastCursorTime = System.currentTimeMillis();
289349
while (rs.next()) {
350+
sqlResultDuration += System.currentTimeMillis() - lastCursorTime;
351+
lastCursorTime = System.currentTimeMillis();
352+
290353
index ++;
291354
Log.d(TAG, "\n\n<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n execute while (rs.next()){ index = " + index + "\n\n");
292355

@@ -318,8 +381,10 @@ public JSONObject execute(@NotNull SQLConfig config, boolean unknowType) throws
318381

319382
if (StringUtil.isEmpty(sqlTable, true)) {
320383
if (toFindJoin) { // 在主表字段数量内的都归属主表
384+
long startTime3 = System.currentTimeMillis();
321385
sqlTable = rsmd.getTableName(i); // SQL 函数甚至部分字段都不返回表名，当然如果没传 @column 生成的 Table.* 则返回的所有字段都会带表名
322-
386+
sqlResultDuration += System.currentTimeMillis() - startTime3;
387+
323388
if (StringUtil.isEmpty(sqlTable, true)) { // hasJoin 已包含这个判断 && joinList != null) {
324389

325390
int nextViceColumnStart = lastViceColumnStart; // 主表没有 @column 时会偏小 lastViceColumnStart
@@ -588,12 +653,19 @@ protected void executeAppJoin(SQLConfig config, List<JSONObject> resultList, Map
588653

589654
int index = -1;
590655

656+
long startTime2 = System.currentTimeMillis();
591657
ResultSetMetaData rsmd = rs.getMetaData();
592658
final int length = rsmd.getColumnCount();
593-
659+
sqlResultDuration += System.currentTimeMillis() - startTime2;
660+
594661
JSONObject result;
595662
String cacheSql;
663+
664+
long lastCursorTime = System.currentTimeMillis();
596665
while (rs.next()) { //FIXME 同时有 @ APP JOIN 和 < 等 SQL JOIN 时，next = false 总是无法进入循环，导致缓存失效，可能是连接池或线程问题
666+
sqlResultDuration += System.currentTimeMillis() - lastCursorTime;
667+
lastCursorTime = System.currentTimeMillis();
668+
597669
index ++;
598670
Log.d(TAG, "\n\n<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n executeAppJoin while (rs.next()){ index = " + index + "\n\n");
599671

@@ -708,21 +780,31 @@ protected List<JSONObject> onPutTable(@NotNull SQLConfig config, @NotNull Result
708780

709781
protected String getKey(@NotNull SQLConfig config, @NotNull ResultSet rs, @NotNull ResultSetMetaData rsmd
710782
, final int tablePosition, @NotNull JSONObject table, final int columnIndex, Map<String, JSONObject> childMap) throws Exception {
711-
String key = rsmd.getColumnLabel(columnIndex);// dotIndex < 0 ? lable : lable.substring(dotIndex + 1);
783+
long startTime = System.currentTimeMillis();
784+
String key = rsmd.getColumnLabel(columnIndex); // dotIndex < 0 ? lable : lable.substring(dotIndex + 1);
785+
sqlResultDuration += System.currentTimeMillis() - startTime;
786+
712787
if (config.isHive()) {
713788
String table_name = config.getTable();
714-
if(AbstractSQLConfig.TABLE_KEY_MAP.containsKey(table_name)) table_name = AbstractSQLConfig.TABLE_KEY_MAP.get(table_name);
789+
if (AbstractSQLConfig.TABLE_KEY_MAP.containsKey(table_name)) {
790+
table_name = AbstractSQLConfig.TABLE_KEY_MAP.get(table_name);
791+
}
715792
String pattern = "^" + table_name + "\\." + "[a-zA-Z]+$";
716793
boolean isMatch = Pattern.matches(pattern, key);
717-
if(isMatch) key = key.split("\\.")[1];
794+
if (isMatch) {
795+
key = key.split("\\.")[1];
796+
}
718797
}
719798
return key;
720799
}
721800

722801
protected Object getValue(@NotNull SQLConfig config, @NotNull ResultSet rs, @NotNull ResultSetMetaData rsmd
723802
, final int tablePosition, @NotNull JSONObject table, final int columnIndex, String lable, Map<String, JSONObject> childMap) throws Exception {
724803

804+
long startTime = System.currentTimeMillis();
725805
Object value = rs.getObject(columnIndex);
806+
sqlResultDuration += System.currentTimeMillis() - startTime;
807+
726808
// Log.d(TAG, "name:" + rsmd.getColumnName(i));
727809
// Log.d(TAG, "lable:" + rsmd.getColumnLabel(i));
728810
// Log.d(TAG, "type:" + rsmd.getColumnType(i));
@@ -799,7 +881,10 @@ else if (value instanceof Clob) { //SQL Server TEXT 类型 居然走这个
799881
@Override
800882
public boolean isJSONType(@NotNull SQLConfig config, ResultSetMetaData rsmd, int position, String lable) {
801883
try {
884+
long startTime = System.currentTimeMillis();
802885
String column = rsmd.getColumnTypeName(position);
886+
sqlResultDuration += System.currentTimeMillis() - startTime;
887+
803888
//TODO CHAR和JSON类型的字段，getColumnType返回值都是1 ，如果不用CHAR，改用VARCHAR，则可以用上面这行来提高性能。
804889
//return rsmd.getColumnType(position) == 1;
805890

@@ -965,19 +1050,28 @@ public void close() {
9651050

9661051
@Override
9671052
public ResultSet executeQuery(@NotNull SQLConfig config) throws Exception {
968-
return getStatement(config).executeQuery(); //PreparedStatement 不用传 SQL
1053+
PreparedStatement s = getStatement(config);
1054+
// 不准，getStatement 有时比 execute sql 更耗时 executedSQLStartTime = System.currentTimeMillis();
1055+
ResultSet rs = s.executeQuery(); //PreparedStatement 不用传 SQL
1056+
// executedSQLEndTime = System.currentTimeMillis();
1057+
return rs;
9691058
}
9701059

9711060
@Override
9721061
public int executeUpdate(@NotNull SQLConfig config) throws Exception {
9731062
PreparedStatement s = getStatement(config);
974-
int count = s.executeUpdate(); //PreparedStatement 不用传 SQL
975-
if (config.isHive() && count==0) count = 1;
976-
977-
if (config.getMethod() == RequestMethod.POST && config.getId() == null) { //自增id
1063+
// 不准，getStatement 有时比 execute sql 更耗时 executedSQLStartTime = System.currentTimeMillis();
1064+
int count = s.executeUpdate(); // PreparedStatement 不用传 SQL
1065+
// executedSQLEndTime = System.currentTimeMillis();
1066+
1067+
if (count <= 0 && config.isHive()) {
1068+
count = 1;
1069+
}
1070+
1071+
if (config.getId() == null && config.getMethod() == RequestMethod.POST) { // 自增id
9781072
ResultSet rs = s.getGeneratedKeys();
9791073
if (rs != null && rs.next()) {
980-
config.setId(rs.getLong(1));//返回插入的主键id
1074+
config.setId(rs.getLong(1)); //返回插入的主键id FIXME Oracle 拿不到
9811075
}
9821076
}
9831077

‎APIJSONORM/src/main/java/apijson/orm/SQLExecutor.java‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -115,5 +115,8 @@ public interface SQLExecutor {
115115

116116
int getExecutedSQLCount();
117117

118-
118+
long getExecutedSQLDuration();
119+
120+
long getSqlResultDuration();
121+
119122
}

0 commit comments

Comments
 (0)