subsys-dfx-hitracemeter.md 18.2 KB
Newer Older
S
shawn_he 已提交
1 2 3 4 5 6 7 8 9 10 11 12 13
# HiTraceMeter

## Introduction

HiTraceMeter is the OpenHarmony subsystem that provides APIs to implement call chain trace throughout a service process. With HiTraceMeter, you can quickly obtain the run log specific to the call chain of a service process and locate faults in inter-device, inter-process, or inter-thread communications. HiTraceMeter supports event logging in user mode and can collect trace data in user mode and kernel mode for performance tracing and analysis.

## Basic Concepts

The HiTraceMeter subsystem consists of three parts:
- JS/C++ HiTraceMeter APIs for application logging
- hitrace CLI tool for data collection
- smartperf tool for graphical data analysis 

S
shawn_he 已提交
14
Wherein, HiTraceMeter APIs and the hitrace CLI tool run on the device side, and the smartperf tool runs on the PC side. HiTraceMeter APIs are provided in C++ and JS for event logging, which aims to generate the trace data necessary for performance tracing and analysis during the development process.
S
shawn_he 已提交
15 16 17 18 19

The hitrace CLI tool is used to collect trace data. It captures trace data flows and saves the data as a text file.

The smartperf tool allows you to perform data analysis manually or use the analysis script for automated data analysis. If you want to get the data analysis done automatically, you need to supply the data file generated by the hitrace CLI tool as the input for the smartperf tool.

S
shawn_he 已提交
20
  Traces data is classified by trace tag or trace category. Generally, one device subsystem corresponds to one tag. The tag is passed as the **Tag** parameter to event logging APIs. When you use the hitrace CLI tool to collect trace data, only the trace data specified by the **Tag** parameter is collected. Trace data of applications is fixedly labeled as **APP Tag**, and therefore, no **Tag** parameter needs to be passed to JS APIs. The following is a list of trace tags supported by HiTraceMeter. You can view the tags in [hitrace_meter.h](https://gitee.com/openharmony/hiviewdfx_hitrace/blob/master/interfaces/native/innerkits/include/hitrace_meter/hitrace_meter.h).
S
shawn_he 已提交
21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72

```cpp
constexpr uint64_t HITRACE_TAG_NEVER = 0; // This tag is never enabled.
constexpr uint64_t HITRACE_TAG_ALWAYS = (1ULL << 0); // This tag is always enabled.
constexpr uint64_t HITRACE_TAG_DLP_CREDENTIAL = (1ULL << 21); // This tag is dlp credential service.
constexpr uint64_t HITRACE_TAG_ACCESS_CONTROL = (1ULL << 22); // This tag is access control tag.
constexpr uint64_t HITRACE_TAG_NET = (1ULL << 23); // Net tag.
constexpr uint64_t HITRACE_TAG_NWEB = (1ULL << 24); // NWeb tag.
constexpr uint64_t HITRACE_TAG_HUKS = (1ULL << 25); // This tag is huks.
constexpr uint64_t HITRACE_TAG_USERIAM = (1ULL << 26); // This tag is useriam.
constexpr uint64_t HITRACE_TAG_DISTRIBUTED_AUDIO = (1ULL << 27); // Distributed audio tag.
constexpr uint64_t HITRACE_TAG_DLSM = (1ULL << 28); // device security level tag.
constexpr uint64_t HITRACE_TAG_FILEMANAGEMENT = (1ULL << 29); // filemanagement tag.
constexpr uint64_t HITRACE_TAG_OHOS = (1ULL << 30); // OHOS generic tag.
constexpr uint64_t HITRACE_TAG_ABILITY_MANAGER = (1ULL << 31); // Ability Manager tag.
constexpr uint64_t HITRACE_TAG_ZCAMERA = (1ULL << 32); // Camera module tag.
constexpr uint64_t HITRACE_TAG_ZMEDIA = (1ULL << 33); // Media module tag.
constexpr uint64_t HITRACE_TAG_ZIMAGE = (1ULL << 34); // Image module tag.
constexpr uint64_t HITRACE_TAG_ZAUDIO = (1ULL << 35); // Audio module tag.
constexpr uint64_t HITRACE_TAG_DISTRIBUTEDDATA = (1ULL << 36); // Distributeddata manager module tag.
constexpr uint64_t HITRACE_TAG_MDFS = (1ULL << 37); // Mobile distributed file system tag.
constexpr uint64_t HITRACE_TAG_GRAPHIC_AGP = (1ULL << 38); // Graphic module tag.
constexpr uint64_t HITRACE_TAG_ACE = (1ULL << 39); // ACE development framework tag.
constexpr uint64_t HITRACE_TAG_NOTIFICATION = (1ULL << 40); // Notification module tag.
constexpr uint64_t HITRACE_TAG_MISC = (1ULL << 41); // Notification module tag.
constexpr uint64_t HITRACE_TAG_MULTIMODALINPUT = (1ULL << 42); // Multi modal module tag.
constexpr uint64_t HITRACE_TAG_SENSORS = (1ULL << 43); // Sensors mudule tag.
constexpr uint64_t HITRACE_TAG_MSDP = (1ULL << 44); // Multimodal Sensor Data Platform module tag.
constexpr uint64_t HITRACE_TAG_DSOFTBUS = (1ULL << 45); // Distributed Softbus tag.
constexpr uint64_t HITRACE_TAG_RPC = (1ULL << 46); // RPC and IPC tag.
constexpr uint64_t HITRACE_TAG_ARK = (1ULL << 47); // ARK tag.
constexpr uint64_t HITRACE_TAG_WINDOW_MANAGER = (1ULL << 48); // window manager tag.
constexpr uint64_t HITRACE_TAG_ACCOUNT_MANAGER = (1ULL << 49); // account manager tag.
constexpr uint64_t HITRACE_TAG_DISTRIBUTED_SCREEN = (1ULL << 50); // Distributed screen tag.
constexpr uint64_t HITRACE_TAG_DISTRIBUTED_CAMERA = (1ULL << 51); // Distributed camera tag.
constexpr uint64_t HITRACE_TAG_DISTRIBUTED_HARDWARE_FWK = (1ULL << 52); // Distributed hardware fwk tag.
constexpr uint64_t HITRACE_TAG_GLOBAL_RESMGR = (1ULL << 53); // Global resource manager tag.
constexpr uint64_t HITRACE_TAG_DEVICE_MANAGER = (1ULL << 54); // Distributed hardware devicemanager tag.
constexpr uint64_t HITRACE_TAG_SAMGR = (1ULL << 55); // SA tag.
constexpr uint64_t HITRACE_TAG_POWER = (1ULL << 56); // power manager tag.
constexpr uint64_t HITRACE_TAG_DISTRIBUTED_SCHEDULE = (1ULL << 57); // Distributed schedule tag.
constexpr uint64_t HITRACE_TAG_DEVICE_PROFILE = (1ULL << 58); // device profile tag.
constexpr uint64_t HITRACE_TAG_DISTRIBUTED_INPUT = (1ULL << 59); // Distributed input tag.
constexpr uint64_t HITRACE_TAG_BLUETOOTH = (1ULL << 60); // bluetooth tag.
constexpr uint64_t HITRACE_TAG_ACCESSIBILITY_MANAGER = (1ULL << 61); // accessibility manager tag.
constexpr uint64_t HITRACE_TAG_APP = (1ULL << 62); // App tag.

constexpr uint64_t HITRACE_TAG_LAST = HITRACE_TAG_APP;
constexpr uint64_t HITRACE_TAG_NOT_READY = (1ULL << 63); // Reserved for initialization.
constexpr uint64_t HITRACE_TAG_VALID_MASK = ((HITRACE_TAG_LAST - 1) | HITRACE_TAG_LAST);
```

S
shawn_he 已提交
73
## Implementation Principles
S
shawn_he 已提交
74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108

HiTraceMeter provides the hitrace CLI tool for capturing trace data in user mode and kernel mode, and provides C++ (innerkits) and JS (kits) APIs for event logging in user mode. Through extending kernel's ftrace functionality, HiTraceMeter can use the trace_marker node of ftrace to write the data, which is written into the user space by event logging APIs, to the kernel buffer. The following figure shows the basic HiTraceMeter architecture.



![HiTraceMeter architecture](figure/HiTraceMeter.png)




## Constraints

- The implementation of HiTraceMeter functions and APIs depends on the ftrace functionality, a framework provided by the kernel. It enables developers to add more trace functions via plug-ins. Therefore, make sure that ftrace is enabled before you use HiTraceMeter.
 For most Linux kernels, ftrace is enabled by default. For details, see the ftrace documentation you may obtain.
- HiTraceMeter is available only for the mini system and standard system.



# HiTraceMeter Development

HiTraceMeter development focuses on two parts: JS/C++ event logging APIs and the hitrace CLI tool.




## When to Use

You may encounter unexpected issues like app freezing during app development or need to view the code's call chain during code debugging. With the APIs provided by HiTraceMeter, you'll be able to trace the application delay and call chain to identify performance problems.

## Available APIs

Only C++ APIs are now open for system developers. If you're developing a JS app, skip this section. The following table describes the APIs applicable to the standard system. You can find the APIs in [hitrace_meter.h](https://gitee.com/openharmony/hiviewdfx_hitrace/blob/master/interfaces/native/innerkits/include/hitrace_meter/hitrace_meter.h).

**Table 1** Sync APIs

S
shawn_he 已提交
109
| Sync trace                                                   | Function     |Parameter Description     |
S
shawn_he 已提交
110 111 112 113 114 115 116 117 118
| :----------------------------------------------------------- | ------------- |------------- |
| void StartTrace(uint64_t label, const std::string& value, float limit = -1); | Starts a synchronous trace.|**label**: trace category.<br>**value**: trace data that indicates the specific status, such as the memory size and queue length.|
| void FinishTrace(uint64_t label);                            | Stops a synchronous trace.|**label**: trace category.|


**StartTrace** and **FinishTrace** must be used in pairs, and **FinishTrace** matches the latest **StartTrace**. The two APIs can be used in nested mode. The stack data structure is used for matching during trace data parsing. The **limit** parameter is used for flow control, and you are advised to use the default value.

**Table 2** Async APIs

S
shawn_he 已提交
119
| Async trace                                                  | Function     |Parameter Description   |
S
shawn_he 已提交
120 121 122 123 124 125 126 127 128 129
| ------------------------------------------------------------ | ------------- |------------- |
| void StartAsyncTrace(uint64_t label, const std::string& value, int32_t taskId, float limit = -1); | Starts an asynchronous trace.| **label**: trace category.<br>**value**: trace data that indicates the specific status, such as the memory size and queue length.<br>**taskId**: ID used to indicate the association of APIs in an asynchronous trace.|
| void FinishAsyncTrace(uint64_t label, const std::string& value, int32_t taskId); | Stops an asynchronous trace.| **label**: trace category.<br>**value**: trace data that indicates the specific status, such as the memory size and queue length.<br>**taskId**: ID used to indicate the association of APIs in an asynchronous trace.|



The trace data of **StartAsyncTrace** and **FinishAsyncTrace** is matched based on **value** and **taskId**, and therefore, the two APIs can be used without a strict sequence. In C++ applications, asynchronous traces are seldom used.

**Table 3** Counter APIs

S
shawn_he 已提交
130
| Counter Trace                                                | Function |Parameter Description |
S
shawn_he 已提交
131
| ------------------------------------------------------------ | --------- |--------- |
S
shawn_he 已提交
132
| void CountTrace(uint64_t label, const std::string& name, int64_t); | Count trace.|**label**: trace category.<br>**name**: trace name displayed in the IDE.|
S
shawn_he 已提交
133 134 135 136 137 138 139 140 141 142 143 144 145 146


## How to Develop
1. Add the build dependencies to the build configuration file **base\hiviewdfx\hitrace\cmd\BUILD.gn**.

    ```
    external_deps = [ "hitrace_native:hitrace_meter"]
    ```
2. Add the header file dependencies.

    ```cpp
    #include "hitrace_meter.h"// Header file for defining APIs
    ```

S
shawn_he 已提交
147
3. When calling an API, pass the trace value as an input parameter. The trace tags currently supported are listed in **hitrace_meter.h**. Assume that the trace tag is **OHOS** and trace data of **func1** and **func2** needs to be captured. After the hitrace command is executed in the shell, the trace data is automatically captured. The captured data includes the function call process and the memory and time consumed during this process. You can use the data to analyze the call process to identify performance problems.
S
shawn_he 已提交
148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166


```cpp
#include "hitrace_meter.h" // Include hitrace_meter.h
using namespace std;
    
int main()
{
     uint64_t label = BYTRACE_TAG_OHOS;
     sleep(1);
     CountTrace(label, "count number", 2000);  // Integer trace
 
     StartTrace(label, "func1Trace", -1); // Trace start point of func1Start
     sleep(1);
     StartTrace(label, "func2Trace", -1);   // Trace start point of func2Start
     sleep(2);
     FinishTrace (label); // Trace end point of func2Trace
     sleep(1);
     FinishTrace(label);   // Trace end point of func1Trace
S
shawn_he 已提交
167 168 169 170
        
     StartAsyncTrace(label, "asyncTrace1", 1234); // Trace start point of asyncTrace1  
     FinishAsyncTrace(label, "asyncTrace1", 1234); // Trace end point of asyncTrace2
     
S
shawn_he 已提交
171
     return 0;
S
shawn_he 已提交
172 173
 }
    ```
S
shawn_he 已提交
174

S
shawn_he 已提交
175 176 177 178 179 180 181
4. On completion of HiTraceMeter building and deployment, start a trace. After you run the application in the shell on the device, trace data will be captured automatically.

    ```
    hdc_std shell hitrace -t 10 ohos > .\myapp_demo.ftrace
    ```

 You can open the captured data by clicking **Open trace file** in the smartperf tool or dragging the data to the graphics area. For details, see [smartperf](https://toscode.gitee.com/openharmony-sig/smartperf).
S
shawn_he 已提交
182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297


## Verification

The following is a demo debugging process, where the **StartTrace** and **FinishTrace** APIs are used in synchronization mode.

1. Write the test code file [hitrace_example.cpp](https://gitee.com/openharmony/hiviewdfx_hitrace/blob/master/cmd/example/hitrace_example.cpp) by adding the **StartTrace** and **FinishTrace** APIs to the code.

    ```cpp
    int main()
    {
        thread t1(ThreadFunc1);
        t1.join();
    
        StartTrace(LABEL, "testStart");
        sleep(SLEEP_ONE_SECOND);
    
        StartTrace(LABEL, "funcAStart", SLEEP_ONE_SECOND); // Trace start point
        FuncA();
        FinishTrace(LABEL);
        sleep(SLEEP_TWO_SECOND);
    
        thread t2(ThreadFunc2);
        t2.join();
    
        StartTrace(LABEL, "funcBStart", SLEEP_TWO_SECOND);
        FuncB();
        FinishTrace(LABEL);// Trace end point
        sleep(SLEEP_TWO_SECOND);
    
        sleep(SLEEP_ONE_SECOND);
        FinishTrace(LABEL);
        FuncC();
    
        return 0;
    }
    ```

2. Modify the **base\hiviewdfx\hitrace\cmd\BUILD.gn** file, and start building.

    ```
    ohos_executable("hitrace_example") {
      sources = [ "example/hitrace_example.cpp" ]
    
      external_deps = [ "hitrace_native:hitrace_meter" ]
    
      subsystem_name = "hiviewdfx"
      part_name = "hitrace_native"
    }
    
    group("hitrace_target") {
      deps = [
        ":hitrace",
        ":hitrace_example",
      ]
    }
    ```

3. Place the **hitrace_example** executable file in the **/system/bin** directory of the device, and run the following commands in sequence in the shell:

    ```shell
    hitrace --trace_begin ohos
    hitrace_exampe
    hitrace --trace_dump
    ```

    If the expected trace value is present in the trace data, the capture of trace data is successful. For example:

    ```
    <...>-1651    (-------) [002] ....   327.194136: tracing_mark_write: S|1650|H:testAsync 111
    <...>-1650    (-------) [001] ....   332.197640: tracing_mark_write: B|1650|H:testStart
    <...>-1650    (-------) [001] ....   333.198018: tracing_mark_write: B|1650|H:funcAStart
    <...>-1650    (-------) [001] ....   334.198507: tracing_mark_write: E|1650|
    <...>-1654    (-------) [003] ....   341.201673: tracing_mark_write: F|1650|H:testAsync 111
    <...>-1650    (-------) [001] ....   341.202168: tracing_mark_write: B|1650|H:funcBStart
    <...>-1650    (-------) [001] ....   343.202557: tracing_mark_write: E|1650|
    <...>-1650    (-------) [001] ....   346.203178: tracing_mark_write: E|1650|
    <...>-1650    (-------) [001] ....   346.203457: tracing_mark_write: C|1650|H:count number 1
    <...>-1650    (-------) [001] ....   347.203818: tracing_mark_write: C|1650|H:count number 2
    <...>-1650    (-------) [001] ....   348.204207: tracing_mark_write: C|1650|H:count number 3
    <...>-1650    (-------) [001] ....   349.204473: tracing_mark_write: C|1650|H:count number 4
    <...>-1650    (-------) [001] ....   350.204851: tracing_mark_write: C|1650|H:count number 5
    <...>-1655    (-------) [001] ....   365.944658: tracing_mark_write: trace_event_clock_sync: realtime_ts=1502021460925
    <...>-1655    (-------) [001] ....   365.944686: tracing_mark_write: trace_event_clock_sync: parent_ts=365.944641
    ```



# Using the hitrace CLI Tool

The hitrace CLI tool is an executable binary program. On an OpenHarmony-powered device, you can run the following commands in the shell to capture kernel's running data.

**Table 4** Command list

| Option                         | Description                                                  |
| ------------------------------ | ------------------------------------------------------------ |
| -h, --help                    | Views the help Information.                                              |
| -b *n*, --buffer_size *n*         | Sets the buffer size for trace data in KB. The default value is **2048**.              |
| -t *n*, --time *n*                | Sets the trace uptime in seconds, which depends on the time required for analysis.|
| --trace_clock clock            | Sets the type of the clock for adding a timestamp to a trace. The value can be **boot** (default), **global**, **mono**, **uptime**, or **perf**.|
| --trace_begin                  | Starts capturing trace data.                                                 |
| --trace_dump                   | Dumps trace data to the specified position. The default position is the console.                          |
| --trace_finish                 | Stops capturing trace data and dumps trace data to the specified position. The default position is the console.           |
| -l, --list_categories         | Lists the trace categories supported by the device.                                   |
| --overwrite                    | Sets the action to take when the buffer is full. If this option is used, the latest trace data is discarded. If this option is not used, the earliest trace data is discarded (default).  |
| -o *filename*, --output *filename*| Outputs trace data to the specified file.                                      |
| -z                             | Compresses the trace data.                                         |

Examples:

- Query supported labels.

  ```
  hitrace -l
  ```

S
shawn_he 已提交
298
  Alternatively, run the following command:
S
shawn_he 已提交
299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340

  ```
  hitrace --list_categories
  ```


- Trace ability information for 10 seconds and store the trace data in a buffer of 4 MB.

  ```
  hitrace -b 4096 -t 10 --overwrite ability > /data/log/mytrace.ftrace
  ```


- Set the clock type to **mono**.

  ```
  hitrace --trace_clock mono  -b 4096 -t 10 --overwrite ability > /data/log/mytrace.ftrace
  ```


- Compress the trace data.

  ```
  hitrace -z  -b 4096 -t 10 --overwrite ability > /data/log/mytrace.ftrace
  ```



# FAQs

### Incomplete or Empty Data Captured by hitrace

####   Symptom

  The data captured by running the hitrace command is incomplete or no data is captured.

####   Solution

  Check the value of the **-t** and **-b** parameters. If the value is too small, data loss will occur. You are advised to set **-t** to **60** and **-b** to **204800** to increase the trace capture time and buffer, respectively.



S
shawn_he 已提交
341
# Reference
S
shawn_he 已提交
342 343

For details about HiTraceMeter, see [hiviewdfx_hitrace: A Lightweight Distributed Tracing](https://gitee.com/openharmony/hiviewdfx_hitrace).