database/doris
2
0
Fork 0
Code Issues Pull Requests Actions 3 Packages Projects Releases Wiki Activity

[fix](profile) modify load profile some bugs and docs (#17533)

Browse Source 
1. 'insert into' profile has 'insert' type, can not query by 'load' type
2. 'insert into' profile does not have job_id, can not query by job_id. so put all profiles key with query_id
3. 'broker load' profile does not have some infos, npe
This commit is contained in:
xueweizhang
2023-03-09 11:58:40 +08:00
committed by GitHub
parent 4ef46159ae
commit 2d027282f3
9 changed files with 198 additions and 76 deletions
Download Patch File Download Diff File Expand all files Collapse all files

75
docs/en/docs/advanced/best-practice/import-analysis.md
View File

@ -68,12 +68,43 @@ Then submit a Broker Load import request and wait until the import execution com
We can get the Profile list first with the following command:
```sql
mysql> show load profile "/";
+---------+------+-----------+------+------------+- --------------------+---------------------------------+------- ----+------------+
| QueryId | User | DefaultDb | SQL | QueryType | StartTime | EndTime | TotalTime | QueryState |
+---------+------+-----------+------+------------+- --------------------+---------------------------------+------- ----+------------+
| 10441 | N/A | N/A | N/A | Load | 2021-04-10 22:15:37 | 2021-04-10 22:18:54 | 3m17s | N/A |
+---------+------+-----------+------+------------+- --------------------+---------------------------------+------- ----+------------+
mysql> show load profile "/"\G
*************************** 1. row ***************************
JobId: 20010
QueryId: 980014623046410a-af5d36f23381017f
User: root
DefaultDb: default_cluster:test
SQL: LOAD LABEL xxx
QueryType: Load
StartTime: 2023-03-07 19:48:24
EndTime: 2023-03-07 19:50:45
TotalTime: 2m21s
QueryState: N/A
TraceId:
AnalysisTime: NULL
PlanTime: NULL
ScheduleTime: NULL
FetchResultTime: NULL
WriteResultTime: NULL
WaitAndFetchResultTime: NULL
*************************** 2. row ***************************
JobId: N/A
QueryId: 7cc2d0282a7a4391-8dd75030185134d8
User: root
DefaultDb: default_cluster:test
SQL: insert into xxx
QueryType: Load
StartTime: 2023-03-07 19:49:15
EndTime: 2023-03-07 19:49:15
TotalTime: 102ms
QueryState: OK
TraceId:
AnalysisTime: 825.277us
PlanTime: 4.126ms
ScheduleTime: N/A
FetchResultTime: 0ns
WriteResultTime: 0ns
WaitAndFetchResultTime: N/A
````
This command will list all currently saved import profiles. Each line corresponds to one import. where the QueryId column is the ID of the import job. This ID can also be viewed through the SHOW LOAD statement. We can select the QueryId corresponding to the Profile we want to see to see the specific situation.
@ -87,15 +118,15 @@ This command will list all currently saved import profiles. Each line correspond
```sql
mysql> show load profile "/10441";
mysql> show load profile "/980014623046410a-af5d36f23381017f";
+-----------------------------------+------------+
| TaskId | ActiveTime |
| TaskId | ActiveTime |
+-----------------------------------+------------+
| 980014623046410a-88e260f0c43031f1 | 3m14s |
| 980014623046410a-af5d36f23381017f | 3m14s |
+-----------------------------------+------------+
````
As shown in the figure above, it means that the import job 10441 has a total of one subtask, in which ActiveTime indicates the execution time of the longest instance in this subtask.
As shown in the figure above, it means that the import job `980014623046410a-af5d36f23381017f` has a total of one subtask, in which ActiveTime indicates the execution time of the longest instance in this subtask.
2. View the Instance overview of the specified subtask
@ -104,18 +135,18 @@ As shown in the figure above, it means that the import job 10441 has a total of
```sql
mysql> show load profile "/10441/980014623046410a-88e260f0c43031f1";
+-----------------------------------+------------- -----+------------+
| Instances | Host | ActiveTime |
+-----------------------------------+------------- -----+------------+
| 980014623046410a-88e260f0c43031f2 | 10.81.85.89:9067 | 3m7s |
| 980014623046410a-88e260f0c43031f3 | 10.81.85.89:9067 | 3m6s |
| 980014623046410a-88e260f0c43031f4 | 10.81.85.89:9067 | 3m10s |
| 980014623046410a-88e260f0c43031f5 | 10.81.85.89:9067 | 3m14s |
+-----------------------------------+------------- -----+------------+
mysql> show load profile "/980014623046410a-af5d36f23381017f/980014623046410a-af5d36f23381017f";
+-----------------------------------+------------------+------------+
| Instances | Host | ActiveTime |
+-----------------------------------+------------------+------------+
| 980014623046410a-88e260f0c43031f2 | 10.81.85.89:9067 | 3m7s |
| 980014623046410a-88e260f0c43031f3 | 10.81.85.89:9067 | 3m6s |
| 980014623046410a-88e260f0c43031f4 | 10.81.85.89:9067 | 3m10s |
| 980014623046410a-88e260f0c43031f5 | 10.81.85.89:9067 | 3m14s |
+-----------------------------------+------------------+------------+
````
This shows the time-consuming of four instances of the subtask 980014623046410a-88e260f0c43031f1, and also shows the execution node where the instance is located.
This shows the time-consuming of four instances of the subtask 980014623046410a-af5d36f23381017f, and also shows the execution node where the instance is located.
3. View the specific Instance
@ -124,7 +155,7 @@ This shows the time-consuming of four instances of the subtask 980014623046410a-
```sql
mysql> show load profile "/10441/980014623046410a-88e260f0c43031f1/980014623046410a-88e260f0c43031f5"\G
mysql> show load profile "/980014623046410a-af5d36f23381017f/980014623046410a-af5d36f23381017f/980014623046410a-88e260f0c43031f5"\G
**************************** 1. row ******************** ******
Instance:
┌-----------------------------------------┐
@ -166,6 +197,6 @@ This shows the time-consuming of four instances of the subtask 980014623046410a-
└------------------------------------------------- ----┘
````
The figure above shows the specific profiles of each operator of Instance 980014623046410a-88e260f0c43031f5 in subtask 980014623046410a-88e260f0c43031f1.
The figure above shows the specific profiles of each operator of Instance 980014623046410a-af5d36f23381017f in subtask 980014623046410a-88e260f0c43031f5.
Through the above three steps, we can gradually check the execution bottleneck of an import task.

50
docs/en/docs/sql-manual/sql-reference/Show-Statements/SHOW-LOAD-PROFILE.md
View File

@ -59,30 +59,60 @@ This command will list all currently saved import profiles. Each line correspond
1. List all Load Profiles
```sql
mysql> show load profile "/";
+---------+------+-----------+------+-----------+---------------------+---------------------+-----------+------------+
| QueryId | User | DefaultDb | SQL | QueryType | StartTime | EndTime | TotalTime | QueryState |
+---------+------+-----------+------+-----------+---------------------+---------------------+-----------+------------+
| 10441 | N/A | N/A | N/A | Load | 2021-04-10 22:15:37 | 2021-04-10 22:18:54 | 3m17s | N/A |
+---------+------+-----------+------+-----------+---------------------+---------------------+-----------+------------+
2 rows in set (0.00 sec)
mysql> show load profile "/"\G
*************************** 1. row ***************************
JobId: 20010
QueryId: 980014623046410a-af5d36f23381017f
User: root
DefaultDb: default_cluster:test
SQL: LOAD LABEL xxx
QueryType: Load
StartTime: 2023-03-07 19:48:24
EndTime: 2023-03-07 19:50:45
TotalTime: 2m21s
QueryState: N/A
TraceId:
AnalysisTime: NULL
PlanTime: NULL
ScheduleTime: NULL
FetchResultTime: NULL
WriteResultTime: NULL
WaitAndFetchResultTime: NULL
*************************** 2. row ***************************
JobId: N/A
QueryId: 7cc2d0282a7a4391-8dd75030185134d8
User: root
DefaultDb: default_cluster:test
SQL: insert into xxx
QueryType: Load
StartTime: 2023-03-07 19:49:15
EndTime: 2023-03-07 19:49:15
TotalTime: 102ms
QueryState: OK
TraceId:
AnalysisTime: 825.277us
PlanTime: 4.126ms
ScheduleTime: N/A
FetchResultTime: 0ns
WriteResultTime: 0ns
WaitAndFetchResultTime: N/A
````
2. View an overview of the subtasks with imported jobs:
```sql
mysql> show load profile "/10441";
mysql> show load profile "/980014623046410a-af5d36f23381017f";
+-----------------------------------+------------+
| TaskId | ActiveTime |
+-----------------------------------+------------+
| 980014623046410a-88e260f0c43031f1 | 3m14s |
| 980014623046410a-af5d36f23381017f | 3m14s |
+-----------------------------------+------------+
````
3. View the Instance overview of the specified subtask
```sql
mysql> show load profile "/10441/980014623046410a-88e260f0c43031f1";
mysql> show load profile "/980014623046410a-af5d36f23381017f/980014623046410a-af5d36f23381017f/980014623046410a-88e260f0c43031f5"\G
+-----------------------------------+------------------+------------+
| Instances | Host | ActiveTime |
+-----------------------------------+------------------+------------+

57
docs/zh-CN/docs/advanced/best-practice/import-analysis.md
View File

@ -67,12 +67,43 @@ SET is_report_success=true;
我们可以通过如下命令先获取 Profile 列表：
```sql
mysql> show load profile "/";
+---------+------+-----------+------+-----------+---------------------+---------------------+-----------+------------+
| QueryId | User | DefaultDb | SQL | QueryType | StartTime | EndTime | TotalTime | QueryState |
+---------+------+-----------+------+-----------+---------------------+---------------------+-----------+------------+
| 10441 | N/A | N/A | N/A | Load | 2021-04-10 22:15:37 | 2021-04-10 22:18:54 | 3m17s | N/A |
+---------+------+-----------+------+-----------+---------------------+---------------------+-----------+------------+
mysql> show load profile "/"\G
*************************** 1. row ***************************
JobId: 20010
QueryId: 980014623046410a-af5d36f23381017f
User: root
DefaultDb: default_cluster:test
SQL: LOAD LABEL xxx
QueryType: Load
StartTime: 2023-03-07 19:48:24
EndTime: 2023-03-07 19:50:45
TotalTime: 2m21s
QueryState: N/A
TraceId:
AnalysisTime: NULL
PlanTime: NULL
ScheduleTime: NULL
FetchResultTime: NULL
WriteResultTime: NULL
WaitAndFetchResultTime: NULL
*************************** 2. row ***************************
JobId: N/A
QueryId: 7cc2d0282a7a4391-8dd75030185134d8
User: root
DefaultDb: default_cluster:test
SQL: insert into xxx
QueryType: Load
StartTime: 2023-03-07 19:49:15
EndTime: 2023-03-07 19:49:15
TotalTime: 102ms
QueryState: OK
TraceId:
AnalysisTime: 825.277us
PlanTime: 4.126ms
ScheduleTime: N/A
FetchResultTime: 0ns
WriteResultTime: 0ns
WaitAndFetchResultTime: N/A
```
这个命令会列出当前保存的所有导入 Profile。每行对应一个导入。其中 QueryId 列为导入作业的 ID。这个 ID 也可以通过 SHOW LOAD 语句查看拿到。我们可以选择我们想看的 Profile 对应的 QueryId，查看具体情况。
@ -86,15 +117,15 @@ mysql> show load profile "/";
```sql
mysql> show load profile "/10441";
mysql> show load profile "/980014623046410a-af5d36f23381017f";
+-----------------------------------+------------+
| TaskId | ActiveTime |
+-----------------------------------+------------+
| 980014623046410a-88e260f0c43031f1 | 3m14s |
| 980014623046410a-af5d36f23381017f | 3m14s |
+-----------------------------------+------------+
```
如上图，表示 10441 这个导入作业总共有一个子任务，其中 ActiveTime 表示这个子任务中耗时最长的 Instance 的执行时间。
如上图，表示 `980014623046410a-af5d36f23381017f` 这个导入作业总共有一个子任务，其中 ActiveTime 表示这个子任务中耗时最长的 Instance 的执行时间。
2. 查看指定子任务的 Instance 概况
@ -103,7 +134,7 @@ mysql> show load profile "/";
```sql
mysql> show load profile "/10441/980014623046410a-88e260f0c43031f1";
mysql> show load profile "/980014623046410a-af5d36f23381017f/980014623046410a-af5d36f23381017f";
+-----------------------------------+------------------+------------+
| Instances | Host | ActiveTime |
+-----------------------------------+------------------+------------+
@ -114,7 +145,7 @@ mysql> show load profile "/";
+-----------------------------------+------------------+------------+
```
这里展示了 980014623046410a-88e260f0c43031f1 这个子任务的四个 Instance 耗时，并且还展示了 Instance 所在的执行节点。
这里展示了 980014623046410a-af5d36f23381017f 这个子任务的四个 Instance 耗时，并且还展示了 Instance 所在的执行节点。
3. 查看具体 Instance
@ -123,7 +154,7 @@ mysql> show load profile "/";
```sql
mysql> show load profile "/10441/980014623046410a-88e260f0c43031f1/980014623046410a-88e260f0c43031f5"\G
mysql> show load profile "/980014623046410a-af5d36f23381017f/980014623046410a-af5d36f23381017f/980014623046410a-88e260f0c43031f5"\G
*************************** 1. row ***************************
Instance:
┌-----------------------------------------┐
@ -165,6 +196,6 @@ mysql> show load profile "/";
└-----------------------------------------------------┘
```
上图展示了子任务 980014623046410a-88e260f0c43031f1 中，Instance 980014623046410a-88e260f0c43031f5 的各个算子的具体 Profile。
上图展示了子任务 980014623046410a-af5d36f23381017f 中，Instance 980014623046410a-88e260f0c43031f5 的各个算子的具体 Profile。
通过以上3个步骤，我们可以逐步排查一个导入任务的执行瓶颈。

52
docs/zh-CN/docs/sql-manual/sql-reference/Show-Statements/SHOW-LOAD-PROFILE.md
View File

@ -59,30 +59,60 @@ show load profile "/[queryId]"
1. 列出所有的 Load Profile
```sql
mysql> show load profile "/";
+---------+------+-----------+------+-----------+---------------------+---------------------+-----------+------------+
| QueryId | User | DefaultDb | SQL | QueryType | StartTime | EndTime | TotalTime | QueryState |
+---------+------+-----------+------+-----------+---------------------+---------------------+-----------+------------+
| 10441 | N/A | N/A | N/A | Load | 2021-04-10 22:15:37 | 2021-04-10 22:18:54 | 3m17s | N/A |
+---------+------+-----------+------+-----------+---------------------+---------------------+-----------+------------+
2 rows in set (0.00 sec)
mysql> show load profile "/"\G
*************************** 1. row ***************************
JobId: 20010
QueryId: 980014623046410a-af5d36f23381017f
User: root
DefaultDb: default_cluster:test
SQL: LOAD LABEL xxx
QueryType: Load
StartTime: 2023-03-07 19:48:24
EndTime: 2023-03-07 19:50:45
TotalTime: 2m21s
QueryState: N/A
TraceId:
AnalysisTime: NULL
PlanTime: NULL
ScheduleTime: NULL
FetchResultTime: NULL
WriteResultTime: NULL
WaitAndFetchResultTime: NULL
*************************** 2. row ***************************
JobId: N/A
QueryId: 7cc2d0282a7a4391-8dd75030185134d8
User: root
DefaultDb: default_cluster:test
SQL: insert into xxx
QueryType: Load
StartTime: 2023-03-07 19:49:15
EndTime: 2023-03-07 19:49:15
TotalTime: 102ms
QueryState: OK
TraceId:
AnalysisTime: 825.277us
PlanTime: 4.126ms
ScheduleTime: N/A
FetchResultTime: 0ns
WriteResultTime: 0ns
WaitAndFetchResultTime: N/A
```
2. 查看有导入作业的子任务概况：
```sql
mysql> show load profile "/10441";
mysql> show load profile "/980014623046410a-af5d36f23381017f";
+-----------------------------------+------------+
| TaskId | ActiveTime |
+-----------------------------------+------------+
| 980014623046410a-88e260f0c43031f1 | 3m14s |
| 980014623046410a-af5d36f23381017f | 3m14s |
+-----------------------------------+------------+
```
3. 查看指定子任务的 Instance 概况
```sql
mysql> show load profile "/10441/980014623046410a-88e260f0c43031f1";
mysql> show load profile "/980014623046410a-af5d36f23381017f/980014623046410a-af5d36f23381017f";
+-----------------------------------+------------------+------------+
| Instances | Host | ActiveTime |
+-----------------------------------+------------------+------------+
@ -96,7 +126,7 @@ show load profile "/[queryId]"
4. 继续查看某一个具体的 Instance 上各个算子的详细 Profile
```sql
mysql> show load profile "/10441/980014623046410a-88e260f0c43031f1/980014623046410a-88e260f0c43031f5"\G
mysql> show load profile "/980014623046410a-af5d36f23381017f/980014623046410a-af5d36f23381017f/980014623046410a-88e260f0c43031f5"\G
*************************** 1. row ***************************

16
fe/fe-core/src/main/java/org/apache/doris/analysis/ShowLoadProfileStmt.java
View File

@ -27,9 +27,9 @@ import com.google.common.base.Strings;
// For stmt like:
// show load profile "/"; # list all saving load job ids
// show load profile "/10014" # show task ids of specified job
// show load profile "/10014/e0f7390f5363419e-b416a2a79996083e/" # show instance list of the task
// show load profile "/10014/e0f7390f5363419e-b416a2a79996083e/e0f7390f5363419e-b416a2a7999" # show instance's graph
// show load profile "/e0f7390f5363419e-xxx" # show task ids of specified job
// show load profile "/e0f7390f5363419e-xxx/e0f7390f5363419e-yyy/" # show instance list of the task
// show load profile "/e0f7390f5363419e-xxx/e0f7390f5363419e-yyy/e0f7390f5363419e-zzz" # show instance's graph
public class ShowLoadProfileStmt extends ShowStmt {
private static final ShowResultSetMetaData META_DATA_TASK_IDS =
ShowResultSetMetaData.builder()
@ -38,7 +38,7 @@ public class ShowLoadProfileStmt extends ShowStmt {
.build();
public enum PathType {
JOB_IDS,
QUERY_IDS,
TASK_IDS,
INSTANCES,
SINGLE_INSTANCE
@ -76,14 +76,14 @@ public class ShowLoadProfileStmt extends ShowStmt {
super.analyze(analyzer);
if (Strings.isNullOrEmpty(idPath)) {
// list all query ids
pathType = PathType.JOB_IDS;
pathType = PathType.QUERY_IDS;
return;
}
if (!idPath.startsWith("/")) {
throw new AnalysisException("Path must starts with '/'");
}
pathType = PathType.JOB_IDS;
pathType = PathType.QUERY_IDS;
String[] parts = idPath.split("/");
if (parts.length > 4) {
throw new AnalysisException("Path must in format '/jobId/taskId/instanceId'");
@ -92,7 +92,7 @@ public class ShowLoadProfileStmt extends ShowStmt {
for (int i = 0; i < parts.length; i++) {
switch (i) {
case 0:
pathType = PathType.JOB_IDS;
pathType = PathType.QUERY_IDS;
continue;
case 1:
jobId = parts[i];
@ -126,7 +126,7 @@ public class ShowLoadProfileStmt extends ShowStmt {
@Override
public ShowResultSetMetaData getMetaData() {
switch (pathType) {
case JOB_IDS:
case QUERY_IDS:
return ShowQueryProfileStmt.META_DATA_QUERY_IDS;
case TASK_IDS:
return META_DATA_TASK_IDS;

18
fe/fe-core/src/main/java/org/apache/doris/common/util/ProfileManager.java
View File

@ -21,6 +21,7 @@ import org.apache.doris.common.AnalysisException;
import org.apache.doris.common.AuthenticationException;
import org.apache.doris.common.Config;
import org.apache.doris.common.DdlException;
import org.apache.doris.common.Pair;
import org.apache.doris.common.profile.MultiProfileTreeBuilder;
import org.apache.doris.common.profile.ProfileTreeBuilder;
import org.apache.doris.common.profile.ProfileTreeNode;
@ -166,9 +167,12 @@ public class ProfileManager {
for (String header : PROFILE_HEADERS) {
element.infoStrings.put(header, summaryProfile.getInfoString(header));
}
RuntimeProfile executionProfile = summaryProfile.getChildList().get(0).first;
for (String header : EXECUTION_HEADERS) {
element.infoStrings.put(header, executionProfile.getInfoString(header));
List<Pair<RuntimeProfile, Boolean>> childList = summaryProfile.getChildList();
if (!childList.isEmpty()) {
RuntimeProfile executionProfile = childList.get(0).first;
for (String header : EXECUTION_HEADERS) {
element.infoStrings.put(header, executionProfile.getInfoString(header));
}
}
MultiProfileTreeBuilder builder = new MultiProfileTreeBuilder(profile);
@ -189,8 +193,8 @@ public class ProfileManager {
}
ProfileElement element = createElement(profile);
String key = isQueryProfile(profile) ? element.infoStrings.get(ProfileManager.QUERY_ID)
: element.infoStrings.get(ProfileManager.JOB_ID);
// 'insert into' does have job_id, put all profiles key with query_id
String key = element.infoStrings.get(ProfileManager.QUERY_ID);
// check when push in, which can ensure every element in the list has QUERY_ID column,
// so there is no need to check when remove element from list.
if (Strings.isNullOrEmpty(key)) {
@ -383,10 +387,6 @@ public class ProfileManager {
}
}
public boolean isQueryProfile(RuntimeProfile profile) {
return "Query".equals(profile.getName());
}
public void setQErrorToProfileElementObject(String queryId, double qError) {
ProfileElement profileElement = findProfileElementObject(queryId);
if (profileElement != null) {

2
fe/fe-core/src/main/java/org/apache/doris/httpv2/controller/QueryProfileController.java
View File

@ -45,7 +45,7 @@ public class QueryProfileController extends BaseController {
private static final String ID = "id";
private static final String DETAIL_COL = "Detail";
private static final Set<String> QUERY_ID_TYPES = ImmutableSet.of("Query", "Insert");
private static final Set<String> QUERY_ID_TYPES = ImmutableSet.of("Query", "Load");
@RequestMapping(path = "/query_profile/{" + ID + "}", method = RequestMethod.GET)
public Object profile(@PathVariable(value = ID) String id) {

2
fe/fe-core/src/main/java/org/apache/doris/qe/ShowExecutor.java
View File

@ -2033,7 +2033,7 @@ public class ShowExecutor {
ShowLoadProfileStmt.PathType pathType = showStmt.getPathType();
List<List<String>> rows = Lists.newArrayList();
switch (pathType) {
case JOB_IDS:
case QUERY_IDS:
rows = ProfileManager.getInstance().getQueryWithType(ProfileManager.ProfileType.LOAD);
break;
case TASK_IDS: {

2
fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java
View File

@ -595,7 +595,7 @@ public class StmtExecutor implements ProfileWriter {
try {
handleInsertStmt();
if (!((InsertStmt) parsedStmt).getQueryStmt().isExplain()) {
queryType = "Insert";
queryType = "Load";
}
} catch (Throwable t) {
LOG.warn("handle insert stmt fail: {}", t.getMessage());