systemtap分析nginx一次http请求函数调用过程

systemtap 工作原理

systemtap 的核心思想是定义一个事件（event），以及给出处理该事件的句柄（Handler）。当一个特定的事件发生时，内核运行该处理句柄，就像快速调用一个子函数一样，处理完之后恢复到内核原始状态。这里有两个概念：

事件（Event）：systemtap 定义了很多种事件，例如进入或退出某个内核函数、定时器时间到、整个systemtap会话启动或退出等等。
句柄（Handler）：就是一些脚本语句，描述了当事件发生时要完成的工作，通常是从事件的上下文提取数据，将它们存入内部变量中，或者打印出来。

Systemtap 工作原理是通过将脚本语句翻译成C语句，编译成内核模块。模块加载之后，将所有探测的事件以钩子的方式挂到内核上，当任何处理器上的某个事件发生时，相应钩子上句柄就会被执行。最后，当systemtap会话结束之后，钩子从内核上取下，移除模块。整个过程用一个命令 stap 就可以完成。上面只是简单的原理，更多背后的机理参考网上资料和相应的论文。

分析nginx http请求处理脚本

参见[知乎][1]

// show_one_req.stap
probe process("/usr/local/openresty/nginx/sbin/nginx").function("ngx_http_*") {
    printf("%s -> %s\n", thread_indent(2), probefunc());
}
probe process("/usr/local/openresty/nginx/sbin/nginx").function("ngx_http_*").return {
    printf("%s <- %s\n", thread_indent(-2), probefunc());
}

1	stap show_one_req.stap -x NGX_WORKER_PID -v

代码调用过程(比较长)

```bash
0 openresty(1551): -> ngx_http_init_connection
24 openresty(1551): <- ngx_event_accept
0 openresty(1551): -> ngx_http_wait_request_handler
10 openresty(1551): -> ngx_http_create_request
16 openresty(1551): <- ngx_http_wait_request_handler
18 openresty(1551): -> ngx_http_process_request_line
23 openresty(1551): -> ngx_http_read_request_header
27 openresty(1551): <- ngx_http_process_request_line
30 openresty(1551): -> ngx_http_parse_request_line
36 openresty(1551): <- ngx_http_process_request_line
38 openresty(1551): -> ngx_http_process_request_uri
42 openresty(1551): <- ngx_http_process_request_line
45 openresty(1551): -> ngx_http_process_request_headers
50 openresty(1551): -> ngx_http_read_request_header
54 openresty(1551): <- ngx_http_process_request_headers
57 openresty(1551): -> ngx_http_parse_header_line
62 openresty(1551): <- ngx_http_process_request_headers
65 openresty(1551): -> ngx_http_process_user_agent
70 openresty(1551): <- ngx_http_process_request_headers
72 openresty(1551): -> ngx_http_parse_header_line
76 openresty(1551): <- ngx_http_process_request_headers
78 openresty(1551): -> ngx_http_process_host
83 openresty(1551): -> ngx_http_validate_host
88 openresty(1551): <- ngx_http_process_host
90 openresty(1551): -> ngx_http_set_virtual_server
94 openresty(1551): -> ngx_http_find_virtual_server.isra.2
98 openresty(1551): <- ngx_http_set_virtual_server
99 openresty(1551): <- ngx_http_process_host
101 openresty(1551): <- ngx_http_process_request_headers
103 openresty(1551): -> ngx_http_parse_header_line
107 openresty(1551): <- ngx_http_process_request_headers
109 openresty(1551): -> ngx_http_parse_header_line
113 openresty(1551): <- ngx_http_process_request_headers
115 openresty(1551): -> ngx_http_process_request_header
119 openresty(1551): <- ngx_http_process_request_headers
121 openresty(1551): -> ngx_http_process_request
126 openresty(1551): -> ngx_http_handler
131 openresty(1551): -> ngx_http_core_run_phases
136 openresty(1551): -> ngx_http_core_generic_phase
164 openresty(1551): -> ngx_http_realip_handler
169 openresty(1551): <- ngx_http_core_generic_phase
170 openresty(1551): <- ngx_http_core_run_phases
173 openresty(1551): -> ngx_http_core_rewrite_phase
178 openresty(1551): <- ngx_http_core_run_phases
180 openresty(1551): -> ngx_http_core_rewrite_phase
185 openresty(1551): -> ngx_http_rewrite_handler
189 openresty(1551): <- ngx_http_core_rewrite_phase
191 openresty(1551): <- ngx_http_core_run_phases
193 openresty(1551): -> ngx_http_core_find_config_phase
198 openresty(1551): -> ngx_http_core_find_location
202 openresty(1551): -> ngx_http_core_find_location
207 openresty(1551): -> ngx_http_core_find_location
211 openresty(1551): -> ngx_http_core_find_location
215 openresty(1551): <- ngx_http_core_find_location
217 openresty(1551): <- ngx_http_core_find_config_phase
219 openresty(1551): -> ngx_http_update_location_config
224 openresty(1551): <- ngx_http_core_find_config_phase
226 openresty(1551): <- ngx_http_core_run_phases
228 openresty(1551): -> ngx_http_core_rewrite_phase
232 openresty(1551): <- ngx_http_core_run_phases
234 openresty(1551): -> ngx_http_core_rewrite_phase
238 openresty(1551): -> ngx_http_rewrite_handler
242 openresty(1551): <- ngx_http_core_rewrite_phase
244 openresty(1551): <- ngx_http_core_run_phases
246 openresty(1551): -> ngx_http_core_post_rewrite_phase
250 openresty(1551): <- ngx_http_core_run_phases
253 openresty(1551): -> ngx_http_core_generic_phase
257 openresty(1551): -> ngx_http_realip_handler
261 openresty(1551): <- ngx_http_core_generic_phase
263 openresty(1551): <- ngx_http_core_run_phases
265 openresty(1551): -> ngx_http_core_generic_phase
270 openresty(1551): -> ngx_http_limit_req_handler
276 openresty(1551): <- ngx_http_core_generic_phase
277 openresty(1551): <- ngx_http_core_run_phases
279 openresty(1551): -> ngx_http_core_generic_phase
284 openresty(1551): -> ngx_http_limit_conn_handler
288 openresty(1551): <- ngx_http_core_generic_phase
290 openresty(1551): <- ngx_http_core_run_phases
292 openresty(1551): -> ngx_http_core_access_phase
296 openresty(1551): -> ngx_http_access_handler
301 openresty(1551): <- ngx_http_core_access_phase
303 openresty(1551): <- ngx_http_core_run_phases
305 openresty(1551): -> ngx_http_core_access_phase
310 openresty(1551): -> ngx_http_auth_basic_handler
314 openresty(1551): <- ngx_http_core_access_phase
316 openresty(1551): <- ngx_http_core_run_phases
318 openresty(1551): -> ngx_http_core_post_access_phase
322 openresty(1551): <- ngx_http_core_run_phases
324 openresty(1551): -> ngx_http_core_generic_phase
328 openresty(1551): -> ngx_http_try_files_handler
333 openresty(1551): <- ngx_http_core_generic_phase
335 openresty(1551): <- ngx_http_core_run_phases
337 openresty(1551): -> ngx_http_core_generic_phase
341 openresty(1551): -> ngx_http_mirror_handler
346 openresty(1551): <- ngx_http_core_generic_phase
347 openresty(1551): <- ngx_http_core_run_phases
349 openresty(1551): -> ngx_http_core_content_phase
355 openresty(1551): -> ngx_http_lua_content_handler
362 openresty(1551): -> ngx_http_lua_content_handler
366 openresty(1551): -> ngx_http_lua_content_handler
376 openresty(1551): -> ngx_http_lua_content_handler_inline
391 openresty(1551): -> ngx_http_lua_content_handler_inline
424 openresty(1551): -> ngx_http_lua_cache_loadbuffer
488 openresty(1551): -> ngx_http_lua_cache_load_code
506 openresty(1551): <- ngx_http_lua_cache_loadbuffer
509 openresty(1551): <- ngx_http_lua_content_handler_inline
512 openresty(1551): -> ngx_http_lua_content_by_chunk
517 openresty(1551): -> ngx_http_lua_reset_ctx
523 openresty(1551): -> ngx_http_lua_finalize_threads.isra.2
529 openresty(1551): <- ngx_http_lua_reset_ctx
531 openresty(1551): <- ngx_http_lua_content_by_chunk
534 openresty(1551): -> ngx_http_lua_new_thread
541 openresty(1551): -> ngx_http_lua_create_new_globals_table
547 openresty(1551): <- ngx_http_lua_new_thread
549 openresty(1551): -> ngx_http_lua_new_thread
554 openresty(1551): -> ngx_http_lua_new_thread
562 openresty(1551): <- ngx_http_lua_content_by_chunk
564 openresty(1551): -> ngx_http_lua_content_by_chunk
568 openresty(1551): -> ngx_http_lua_content_by_chunk
577 openresty(1551): -> ngx_http_cleanup_add
582 openresty(1551): <- ngx_http_lua_content_by_chunk
586 openresty(1551): -> ngx_http_lua_run_thread
592 openresty(1551): -> ngx_http_lua_run_thread
598 openresty(1551): -> ngx_http_lua_pcre_malloc_init
602 openresty(1551): <- ngx_http_lua_run_thread
612 openresty(1551): -> ngx_http_lua_ngx_say
619 openresty(1551): -> ngx_http_lua_ngx_echo
624 openresty(1551): -> ngx_http_lua_ngx_echo
631 openresty(1551): -> ngx_http_lua_chain_get_free_buf
637 openresty(1551): <- ngx_http_lua_ngx_echo
643 openresty(1551): -> ngx_http_lua_send_chain_link
648 openresty(1551): -> ngx_http_lua_send_header_if_needed
653 openresty(1551): -> ngx_http_lua_send_header_if_needed
658 openresty(1551): -> ngx_http_set_content_type
663 openresty(1551): <- ngx_http_lua_send_header_if_needed
665 openresty(1551): -> ngx_http_send_header
671 openresty(1551): -> ngx_http_not_modified_header_filter
677 openresty(1551): -> ngx_http_lua_capture_header_filter
683 openresty(1551): -> ngx_http_headers_filter
689 openresty(1551): -> ngx_http_userid_filter
697 openresty(1551): -> ngx_http_charset_header_filter
702 openresty(1551): -> ngx_http_charset_header_filter
708 openresty(1551): -> ngx_http_ssi_header_filter
714 openresty(1551): -> ngx_http_gzip_header_filter
720 openresty(1551): -> ngx_http_range_header_filter
725 openresty(1551): -> ngx_http_chunked_header_filter
731 openresty(1551): -> ngx_http_header_filter
741 openresty(1551): -> ngx_http_write_filter
746 openresty(1551): <- ngx_http_header_filter
748 openresty(1551): <- ngx_http_charset_header_filter
750 openresty(1551): <- ngx_http_charset_header_filter
752 openresty(1551): <- ngx_http_charset_header_filter
754 openresty(1551): <- ngx_http_charset_header_filter
757 openresty(1551): <- ngx_http_charset_header_filter
759 openresty(1551): <- ngx_http_userid_filter
762 openresty(1551): <- ngx_http_headers_filter
764 openresty(1551): <- ngx_http_lua_send_header_if_needed
766 openresty(1551): <- ngx_http_lua_send_header_if_needed
769 openresty(1551): <- ngx_http_lua_send_header_if_needed
771 openresty(1551): <- ngx_http_lua_send_header_if_needed
773 openresty(1551): <- ngx_http_lua_send_chain_link
780 openresty(1551): -> ngx_http_lua_output_filter
787 openresty(1551): -> ngx_http_output_filter
794 openresty(1551): -> ngx_http_range_body_filter
801 openresty(1551): -> ngx_http_copy_filter
807 openresty(1551): -> ngx_http_lua_capture_body_filter
816 openresty(1551): -> ngx_http_trailers_filter
824 openresty(1551): -> ngx_http_charset_body_filter
832 openresty(1551): -> ngx_http_ssi_body_filter
841 openresty(1551): -> ngx_http_postpone_filter
850 openresty(1551): -> ngx_http_gzip_body_filter
856 openresty(1551): -> ngx_http_chunked_body_filter
867 openresty(1551): -> ngx_http_write_filter
873 openresty(1551): <- ngx_http_chunked_body_filter
876 openresty(1551): <- ngx_http_gzip_body_filter
878 openresty(1551): <- ngx_http_ssi_body_filter
880 openresty(1551): <- ngx_http_ssi_body_filter
883 openresty(1551): <- ngx_http_charset_body_filter
885 openresty(1551): <- ngx_http_trailers_filter
887 openresty(1551): <- ngx_http_lua_capture_body_filter
890 openresty(1551): <- ngx_output_chain
894 openresty(1551): <- ngx_http_output_filter
2142 openresty(1551): <- ngx_http_output_filter
2189 openresty(1551): <- ngx_http_lua_output_filter
2203 openresty(1551): <- ngx_http_lua_ngx_echo
2207 openresty(1551): <- ngx_http_lua_ngx_echo
2219 openresty(1551): <- 0x7f93c6d1f6ea
2222 openresty(1551): <- 0x7f93c6d1f6ea
2232 openresty(1551): -> ngx_http_lua_pcre_malloc_done
2312 openresty(1551): <- ngx_http_lua_run_thread
2325 openresty(1551): -> ngx_http_lua_run_thread
2334 openresty(1551): -> ngx_http_lua_run_thread
2339 openresty(1551): -> ngx_http_lua_del_thread.part.9
2354 openresty(1551): <- ngx_http_lua_run_thread
2359 openresty(1551): -> ngx_http_lua_send_chain_link
2365 openresty(1551): -> ngx_http_lua_send_header_if_needed
2369 openresty(1551): <- ngx_http_lua_send_chain_link
2376 openresty(1551): -> ngx_http_discard_request_body
2383 openresty(1551): -> ngx_http_test_expect
2387 openresty(1551): <- ngx_http_discard_request_body
2389 openresty(1551): <- ngx_http_lua_send_chain_link
2392 openresty(1551): -> ngx_http_lua_send_chain_link
2399 openresty(1551): -> ngx_http_send_special
2466 openresty(1551): -> ngx_http_output_filter
2478 openresty(1551): -> ngx_http_range_body_filter
2487 openresty(1551): -> ngx_http_copy_filter
2495 openresty(1551): -> ngx_http_lua_capture_body_filter
2502 openresty(1551): -> ngx_http_trailers_filter
2508 openresty(1551): -> ngx_http_charset_body_filter
2515 openresty(1551): -> ngx_http_ssi_body_filter
2522 openresty(1551): -> ngx_http_postpone_filter
2527 openresty(1551): -> ngx_http_gzip_body_filter
2533 openresty(1551): -> ngx_http_chunked_body_filter
2539 openresty(1551): -> ngx_http_chunked_body_filter
2544 openresty(1551): -> ngx_http_write_filter
2722 openresty(1551): <- ngx_http_chunked_body_filter
2727 openresty(1551): <- ngx_http_gzip_body_filter
2731 openresty(1551): <- ngx_http_ssi_body_filter
2732 openresty(1551): <- ngx_http_ssi_body_filter
2737 openresty(1551): <- ngx_http_charset_body_filter
2740 openresty(1551): <- ngx_http_trailers_filter
2743 openresty(1551): <- ngx_http_lua_capture_body_filter
2746 openresty(1551): <- ngx_output_chain
2753 openresty(1551): <- ngx_http_output_filter
2755 openresty(1551): <- ngx_http_output_filter
2757 openresty(1551): <- ngx_http_send_special
2761 openresty(1551): <- ngx_http_lua_send_chain_link
2765 openresty(1551): <- ngx_http_lua_run_thread
2770 openresty(1551): <- ngx_http_lua_content_by_chunk
2776 openresty(1551): <- ngx_http_lua_content_handler
2778 openresty(1551): <- ngx_http_lua_content_handler
2782 openresty(1551): <- ngx_http_core_content_phase
2786 openresty(1551): -> ngx_http_finalize_request
2796 openresty(1551): -> ngx_http_post_action
2803 openresty(1551): <- ngx_http_finalize_request
2806 openresty(1551): -> ngx_http_finalize_connection
2811 openresty(1551): -> ngx_http_finalize_connection
2817 openresty(1551): -> ngx_http_free_request
2823 openresty(1551): -> ngx_http_lua_request_cleanup_handler
2829 openresty(1551): -> ngx_http_lua_request_cleanup
2836 openresty(1551): -> ngx_http_lua_request_cleanup
2842 openresty(1551): -> ngx_http_lua_finalize_threads.isra.2
2848 openresty(1551): <- ngx_http_free_request
2850 openresty(1551): <- ngx_http_free_request
2852 openresty(1551): <- ngx_http_free_request
2855 openresty(1551): -> ngx_http_log_request
2864 openresty(1551): -> ngx_http_log_handler
2874 openresty(1551): -> ngx_http_script_flush_no_cacheable_variables
2879 openresty(1551): <- ngx_http_log_handler
2882 openresty(1551): -> ngx_http_log_variable_getlen
2915 openresty(1551): -> ngx_http_get_indexed_variable
2953 openresty(1551): -> ngx_http_variable_remote_addr
2960 openresty(1551): <- ngx_http_get_indexed_variable
2962 openresty(1551): <- ngx_http_log_variable_getlen
2965 openresty(1551): -> ngx_http_log_escape.isra.1
2969 openresty(1551): <- ngx_http_log_variable_getlen
2971 openresty(1551): <- ngx_http_log_handler
2973 openresty(1551): -> ngx_http_log_variable_getlen
2977 openresty(1551): -> ngx_http_get_indexed_variable
2982 openresty(1551): -> ngx_http_variable_remote_user
2988 openresty(1551): -> ngx_http_auth_basic_user
2994 openresty(1551): <- ngx_http_variable_remote_user
2996 openresty(1551): <- ngx_http_get_indexed_variable
2997 openresty(1551): <- ngx_http_log_variable_getlen
2999 openresty(1551): <- ngx_http_log_handler
3001 openresty(1551): -> ngx_http_log_variable_getlen
3005 openresty(1551): -> ngx_http_get_indexed_variable
3010 openresty(1551): -> ngx_http_variable_request_line
3016 openresty(1551): <- ngx_http_get_indexed_variable
3018 openresty(1551): <- ngx_http_log_variable_getlen
3019 openresty(1551): -> ngx_http_log_escape.isra.1
3024 openresty(1551): <- ngx_http_log_variable_getlen
3026 openresty(1551): <- ngx_http_log_handler
3027 openresty(1551): -> ngx_http_log_variable_getlen
3031 openresty(1551): -> ngx_http_get_indexed_variable
3036 openresty(1551): -> ngx_http_variable_header
3040 openresty(1551): <- ngx_http_get_indexed_variable
3042 openresty(1551): <- ngx_http_log_variable_getlen
3043 openresty(1551): <- ngx_http_log_handler
3045 openresty(1551): -> ngx_http_log_variable_getlen
3049 openresty(1551): -> ngx_http_get_indexed_variable
3054 openresty(1551): -> ngx_http_variable_header
3058 openresty(1551): <- ngx_http_get_indexed_variable
3059 openresty(1551): <- ngx_http_log_variable_getlen
3062 openresty(1551): -> ngx_http_log_escape.isra.1
3066 openresty(1551): <- ngx_http_log_variable_getlen
3067 openresty(1551): <- ngx_http_log_handler
3070 openresty(1551): -> ngx_http_log_variable
3074 openresty(1551): -> ngx_http_get_indexed_variable
3078 openresty(1551): <- ngx_http_log_variable
3081 openresty(1551): <- ngx_http_log_handler
3084 openresty(1551): -> ngx_http_log_copy_short
3088 openresty(1551): <- ngx_http_log_handler
3090 openresty(1551): -> ngx_http_log_variable
3094 openresty(1551): -> ngx_http_get_indexed_variable
3098 openresty(1551): <- ngx_http_log_variable
3100 openresty(1551): <- ngx_http_log_handler
3102 openresty(1551): -> ngx_http_log_copy_short
3106 openresty(1551): <- ngx_http_log_handler
3108 openresty(1551): -> ngx_http_log_time
3113 openresty(1551): <- ngx_http_log_handler
3114 openresty(1551): -> ngx_http_log_copy_short
3118 openresty(1551): <- ngx_http_log_handler
3120 openresty(1551): -> ngx_http_log_variable
3124 openresty(1551): -> ngx_http_get_indexed_variable
3128 openresty(1551): <- ngx_http_log_variable
3130 openresty(1551): <- ngx_http_log_handler
3132 openresty(1551): -> ngx_http_log_copy_short
3136 openresty(1551): <- ngx_http_log_handler
3137 openresty(1551): -> ngx_http_log_status
3143 openresty(1551): <- ngx_http_log_handler
3145 openresty(1551): -> ngx_http_log_copy_short
3149 openresty(1551): <- ngx_http_log_handler
3151 openresty(1551): -> ngx_http_log_body_bytes_sent
3155 openresty(1551): <- ngx_http_log_handler
3157 openresty(1551): -> ngx_http_log_copy_short
3161 openresty(1551): <- ngx_http_log_handler
3163 openresty(1551): -> ngx_http_log_variable
3167 openresty(1551): -> ngx_http_get_indexed_variable
3171 openresty(1551): <- ngx_http_log_variable
3173 openresty(1551): <- ngx_http_log_handler
3174 openresty(1551): -> ngx_http_log_copy_short
3178 openresty(1551): <- ngx_http_log_handler
3180 openresty(1551): -> ngx_http_log_variable
3184 openresty(1551): -> ngx_http_get_indexed_variable
3189 openresty(1551): <- ngx_http_log_variable
3190 openresty(1551): <- ngx_http_log_handler
3192 openresty(1551): -> ngx_http_log_copy_short
3196 openresty(1551): <- ngx_http_log_handler
3198 openresty(1551): -> ngx_http_log_write
3238 openresty(1551): <- ngx_http_log_handler
3241 openresty(1551): <- ngx_http_log_request
3243 openresty(1551): <- ngx_http_free_request
3249 openresty(1551): <- ngx_http_finalize_connection
3255 openresty(1551): <- ngx_http_core_content_phase
3256 openresty(1551): <- ngx_http_core_content_phase
3259 openresty(1551): <- ngx_http_core_run_phases
3263 openresty(1551): <- ngx_http_process_request
3264 openresty(1551): <- ngx_http_process_request
3267 openresty(1551): -> ngx_http_run_posted_requests
3272 openresty(1551): <- ngx_http_process_request_line
3274 openresty(1551): <- ngx_http_process_request_line
3276 openresty(1551): <- ngx_http_process_request_line
3278 openresty(1551): <- ngx_epoll_process_events
3280 openresty(1551): <- ngx_epoll_process_events
4536 openresty(1551): -> ngx_http_keepalive_handler
4557 openresty(1551): -> ngx_http_close_connection
4648 openresty(1551): <- ngx_epoll_process_events
4651 openresty(1551): <- ngx_epoll_process_events