使用A-Ops火焰图stackprobe进行C程序性能优化

问题背景

我们l7probe探针程序会观测http连接,并对做一些吞吐量、时延等的统计。实际测试中发现该程序在高压力流量下会将CPU打满,因此考虑进行性能优化。
注:被测程序l7probe在这里

测试环境

环境: HCS 821 B010 (OpenEuler-22.03 LTS SP1)
CPU core 8
Memory(MB) 16

问题复现

测试条件

l7probe采用debug模式编包;服务端程序为app.py(处理能力较弱);JMeter施压如下:
image

测试结果

29D3EA1F-982F-4F75-8FF8-0DBA37CD07DB
备注:本篇介绍的性能测试过程,均对被测程序和可能影响程序分别做了绑核操作,http服务端app绑核cpu0~2、l7probe绑核cpu7。

火焰图分析

本次性能优化主要使用了A-Ops火焰图特性,具体介绍和安装参考这里
启动stackprobe,并指定观测l7probe进程:

curl -X PUT http://localhost:9999/flamegraph -d json='{"cmd":{"probe":["oncpu", "mem"]},"snoopers":{"proc_name": [{"comm":"l7probe"}]}, "params": {"pyroscope_server": "71.76.51.175:4040"}, "state": "running"}'

后续测试过程默认成功安装并启动了stackprobe,为了不对被测程序性能造成影响,stackprobe也做了绑核操作,本次测试绑核cpu4。


通过上图火焰图,可以看到目前执行耗时长的前三个函数如下:
top1: __write (怀疑是DEBUG打印引起)
top2: data_stream_parse_frames (用户态消息数据查找边界+报文解析流程)
top3: add_tracker_stats (用records刷新link_hash_table)

优化点一

针对top1,怀疑debug日志打印引起cpu占用过高;
被测程序l7probe关闭debug打印,服务端依然采用app.py,JMeter施压不变测试,测试结果如下:
image
可以看到平均CPU占用优化明显,查看火焰图可以看到,原本__write函数占比几乎没有了。

第二轮测试

火焰图分析

第一轮优化后,测试看到add_tracker_stats调用CPU占比很高,其中主要是lkup_l7_link函数,但是分析代码可知该函数内部只有一个hash查表,目前压测场景hash表只有一个元素,不应该是查找导致的耗时高。因而怀疑是否该函数被调用次数过多。
涉及的源码大致如下:

void l7_parser_tracker(struct l7_mng_s *l7_mng, struct conn_tracker_s* tracker) {
...	
    data_stream_parse_frames(msg_type, &(tracker->send_stream));
    	data_stream_parse_frames(msg_type, &(tracker->recv_stream));

    	// add stats
    	add_tracker_stats(l7_mng, tracker); // 调用次数55074686
...
    	return;
}
void data_stream_parse_frames() {	// 调用次数110149372
    1. peek_raw_data
    2. if raw_data == NULL, return
    3. if raw_data != NULL, proto_find_frame_boundary // 调用次数1016437
}

使用gdb看下每个函数调用次数:


如上图所示,data_stream_parse_frames调用次数和add_tracker_stats调用次数符合代码逻辑;但是data_stream_parse_frames是proto_find_frame_boundary调用次数的100倍!
继续分析add_tracker_stats函数主要是将records中的内容更新到hash表中。依然通过gdb查看调用次数:

由源码可看出,大部分情况中raw_data为NULL,会直接跳出循环。考虑raw_data为NULL的情况是否可以不用add_tracker_stats。gdb下看到事实上大部分都是空的,所以后续的更新link的操作都是无效或者没必要的。

优化点二

避免find_l7_link执行次数过多,执行前加判空操作。

add_tracker_stats {
    // 问题点:函数没有做判断,那么即使records为空也要执行一遍find_l7_link
    // 增加判空操作
    if (tracker->records.record_buf_size == 0){
        return;
    }
    link = find_l7_link(l7_mng, (const struct conn_tracker_s *)tracker);		// hash     find link
    link->stats[REQ_COUNT] += tracker->records.req_count;				// 用    records的数据更新link的内容
    link->stats[RSP_COUNT] += tracker->records.resp_count;
    link->stats[ERR_COUNT] += tracker->records.err_count;				
    for (int i = 0; i < tracker->records.record_buf_size && i < RECORD_BUF_SIZE; i++) {
        ....	// 时延统计相关的计算
    }
}

测试结果

修改后火焰图分析可看出,add_tracker_stats的cpu占比减少很多:


但是测试遇到一个问题:被测程序l7probe在修改前后的CPU占用变化不大;但是火焰图变化很明显。分析是因为修改使得l7probe的处理能力增强,l7probe是epoll_wait等待bpg_perf_buf的数据,等到数据然后处理,这里考虑之前的代码处理能力较低。后续测试降低JMeter压力:采用100线程并发测试。

第三轮测试

火焰图分析

上述火焰图中,可以看到现在data_stream_parse_frames执行时间最长,其中主要是proto_find_frame_boundary函数占用时间长。首先从代码层面优化,目前proto_find_frame_boundary源码如下:

size_t http_find_frame_boundary(enum message_type_t msg_type, struct raw_data_s *raw_data) {
    // 1. Find the first "\r\n\r\n" sub-string position in the raw_data.data
    size_t marker_pos = find_str(raw_data->data, BOUNDARY_MARKER, raw_data->current_pos);

    // 2. Find sub-string: raw_data.data[start_pos, marker_pos]
    // 将字符串拷贝到buf_substr中
    char *buf_substr = substr(raw_data->data + raw_data->current_pos, start_pos, marker_pos - start_pos);

    // 3. Match start_pattern in raw_data.data[start_pos, marker_pos], take the last one as frame boundary
    for (int i = 0; i < patterns_len; i++) {
        size_t current_substr_pos = rfind_str(buf_substr, start_pattern);
    }
}

上述代码主要为了找到报文边界,主要是起始边界,方便后续http解析器处理报文。三个步骤中涉及大内存频繁申请释放,以及多次strlen、strncmp、strncpy等操作,具体参考优化点列举
修改内部代码实现,测试结果如下,可以看到优化效果一般:
3D23BD6B-53C4-41EF-BEB4-08CAFE934569
继续分析发现,http_find_frame_boundary 函数为了找到raw_data边界,主要考虑例如 “GET…PUT…POST…\r\n” 的异常情况,需要获取到POST对应的P的位置;
实际测试中这种情况不多,考虑是否可以为了性能取消执行find_frame_boundary操作

优化点三

参考其他开源项目如http_parser、kindling等,并简化http_find_frame_boundary实现方式:从头查找start_pattern,找到即停止。大致实现如下:

size_t http_find_frame_boundary(enum message_type_t msg_type, struct raw_data_s *raw_data)
{
    // March start_pattern in raw_data.data from raw_data.current_pos
    for (int i = raw_data->current_pos; i < raw_data->data_len; i++) {
        for (int j = 0; j < ARRAY_NR(g_start_patterns); j++) {
            if (strncmp(raw_data->data + i, g_start_patterns[j].name, g_start_patterns[j].name_len) == 0) {
                return i;
            }
        }
    }
    return -1;
}

测试结果

优化后测试结果如下:
A13B12C7-D602-4190-AC10-9E959645AFB9
可以看到CPU占用优化效果明显。其实stackprobe运行过程会在/var/log/gala-gopher/stacktrace/下生成对应的svg文件,比如本轮测试我直接取了/var/log/gala-gopher/stacktrace/oncpu/2024-01-08/2024-01-08-16-52-08-521380.svg文件。浏览器直接打开如下图:


可以看到data_stream_parse_frames 执行时间显著缩小。

第四轮测试

火焰图分析

由上轮压测的火焰图可以看到,目前蓝色方框内的get_http_headers_map函数执行耗时最大。分析代码可知,该函数主要是将报文头的内容以key和value的形式存入hash map中。该hash map使用的地方是parse_request_body/parse_response_body,即解析报文正文的时候。
由于报文头内容本来就少(几条)、使用的少(只需要获取"Content-Length" 和 “Transfer-Encoding”),以及仅在解析正文处使用,考虑删除hash表,直接遍历结构体数组查找

优化点四

删除parse_request_frame/parse_response_frame中get_http_headers_map的调用;
修改parse_request_body/parse_response_body中"Content-Length" 和 "Transfer-Encoding"获取方案:直接遍历数组获取。修改大致如下

// 删除 get_http_headers_map 函数调用
// parse_request_body/parse_response_body增加函数入参,将http_headers数组传递进去
static parse_state_t parse_request_body(struct raw_data_s *raw_data, struct http_header headers[], int num_headers, struct http_message *frame_data)
// parse_request_body/parse_response_body内部直接遍历数组查找
// 新增get_http_header_value_by_key函数
int get_http_header_value_by_key(struct http_header headers[], size_t num_headers, char *key, char *value, int vlen_max)
{
    if (key == NULL || value == NULL) {
        return -1;
    }
    int klen = strlen(key);
    for (size_t i = 0; i < num_headers; i++) {
        if ((headers[i].name_len == klen) && (strncmp(headers[i].name, key, klen) == 0)) {
            int vlen = (headers[i].value_len < vlen_max) ? headers[i].value_len : (vlen_max - 1);
            (void)snprintf(value, vlen + 1, "%s", headers[i].value);
            return 0;
        }
    }
    return -1;
}

测试结果

被测程序l7probe单核100连接下,测试平均CPU占用**5%**左右:
image
同样观察火焰图,可以看到http_headers_map 的执行时长几乎没了,整个parse_request_frame/parse_response_frame的执行时长也少了。

至此,优化暂时告一段落。

2 Likes