Xhprof源码分析

核心监控流程:

  1. 初始化监控:通过xhprof_enable函数,设置函数钩子和统计函数。涉及的主要函数钩子有如下:

    zend_compile_file:当使用include\require\include_one\require_once函数加载文件时,均会经历编译过程。这编译过程就是通过该函数完成。

    zend_execute_ex:php引擎每执行一个函数,均会通过该函数进行调用,像xdebug也是通过该函数建立运行堆栈信息,xhprof也不例外,钩子建立过程。

    _zend_execute_ex = zend_compile_file

    zend_compile_file = hp_execute_ex

    zend_execute_internal:该函数只有xhprof_enable配置了XHPROF_FLAGS_NO_BUILTINS参数时,才会被拦截。

  2. 监控核心过程:被动地监控每个函数的执行,由于函数HOOKER的机制,PHP每执行一个函数都将进入钩子的回调函数中,并在相应的回调函数中执行以下过程:

    BEGIN_PROFILING->function execute->END_PROFILING

    函数式表示如下:

    Function hp_execute_ex() //这是钩子的回调函数。

    {

        BEGIN_PROFILING; //开始分配内存、初始化捕获的开始时间,内存值等

        _zend_execute_ex(); //执行函数内容。

        END_PROFILING; //计算函数执行的成本:CPU和内存

    }

    另外三个函数,也是采用同样的方式。

  3. 结束监控,返回数据。

 

源码分析

  1. 初始化函数钩子。并默认把main()函数当作为监控入口,它是一个虚拟函数,目的是表示监控的开始和结束,xhprof_enable调用表示开始执行该虚拟函数,xhprof_disable表示结束该虚拟函数。

 

 

  1. 由于钩子的拦截关系,PHP引擎每执行一个函数,均会进入相应钩子回调中,如hp_execute_ex函数为例。重点关注两个宏定义,分别是BEGIN_PROFILING和END_PROFILING.

  1. BEGIN_PROFILING和END_PROFILING的定义如下:

    这两个宏完成以下三件事:

    1. 分配栈帧,每一个hp_entry_t结构,是栈结构上的一个元素。它记录了当前函数的开始信息,如当前函数名、递归深度、开始时间、开始内存。

      注:它不保存当前函数的结束信息,结束的信息会减去开始信息,然后把结果输出到另一个数组中。

    2. hp_mode_common_beginfn函数是用于执行压栈动作,并检测栈中是否存在递归函数;hp_mode_common_endfn函数用于执行弹栈动作。
    3. begin_fn_cb函数是用于填充hp_entry_t结构信息,也即是函数的开始信息;end_fn_cb函数是用于计算函数的消耗结果,并把该结果输出到另外一个全局数组中,该数组并没有体现在这两个宏定义中。
  2. 在xhprof实际使用过程中,常会看到如下一些情况,举例说明:

    PHP代码如下:

    Xhprof的图表中输出如下:

    图表中的@1,@2,@3代表什么?这个数字代表这个函数在执行过程中的递归深度,具体算法如下。

    这段源码部份变量解释如下:

    func_hash_counters,全局数组是用于快速判断当前栈列表中是否存在同码函数

    hash_code,记录是函数的hash码,xhprof把函数转换为一个0~255的整数。

    name_hprof,记录是函数的真正名字,如bar这个函数。

    rlvl_hprof,记录的是当前函数在栈列表中深度。

    entries,永远指向栈列表的栈顶。

    综上所述,该段函数的功能是指函数在被压入栈表前,由栈顶向栈底搜索是否存在同名函数,如果栈表已经存在同名函数,则表示当前正在执行函数递归操作,并记录当前函数的递归深度。

    下面函数应该可以加强上述的理解。

    hp_get_entry_name就是获取函数名。

  3. 偶然也会遇到如下一些现象,依旧举例说明。

    Php代码如下:

    Xhprof图表如下:

    load::my/MyTest.php也是一个虚拟的函数,它的功能是代表把MyTest.php由源文件翻译成opcode文件的消耗。关键算法截图如下:

该函数解析如下:

zend_compile_file,该函数是把php源文件翻译成opcode指令。

hp_get_base_filename,是把文件路径,截取最后两段路径名作函数名返回来,如下所示

/alidata/www/xhprof/example/../my/MyTest.php => my/MyTest

/a/b/c/a.php =>c/a

???_op,函数是无法获取函数名字的一个默认名称。

  1. Xhprof_disable()返回原始输出结果。

    源码如下:

    以JSON格式输出原始结果如下:

    {“foo==>bar”:{“ct”:5,”wt”:38,”cpu”:0,”mu”:5008,”pmu”:0},”bar==>bar@1″:{“ct”:5,”wt”:22,”cpu”:0,”mu”:4928,”pmu”:0},”bar@1==>bar@2″:{“ct”:4,”wt”:14,”cpu”:0,”mu”:3888,”pmu”:0},”bar@2==>bar@3″:{“ct”:3,”wt”:9,”cpu”:0,”mu”:2848,”pmu”:0},”bar@3==>bar@4″:{“ct”:2,”wt”:3,”cpu”:0,”mu”:1808,”pmu”:0},”main()==>foo”:{“ct”:1,”wt”:80,”cpu”:0,”mu”:6080,”pmu”:0},”bar@4==>bar@5″:{“ct”:1,”wt”:0,”cpu”:0,”mu”:752,”pmu”:0},”main()==>bar”:{“ct”:1,”wt”:8,”cpu”:0,”mu”:1792,”pmu”:0},”main()”:{“ct”:1,”wt”:114,”cpu”:0,”mu”:9240,”pmu”:0}}

    这个JSON如何转换到以下图表呢?

    从图表虽然很直观,但不能很好的反映出它与原始JSON内容的关系,我们选择其中一项,如bar项,展开其父、我、子,这种爷孙三代关系图,截图如下:

    “foo==>bar”:{“ct”:5,”wt”:38,”cpu”:0,”mu”:5008,”pmu”:0}

    “main()==>bar”:{“ct”:1,”wt”:8,”cpu”:0,”mu”:1792,”pmu”:0}

    “bar==>bar@1”:{“ct”:5,”wt”:22,”cpu”:0,”mu”:4928,”pmu”:0}

    通过对比,可以知道Excl.Wall_Time运算公式如下:

    Excl.Wall_Time = Current Function.Incl.Wall_Time – Child Function.Incl.Wall_Time。

    cpu的消耗,个人认为它与wt消耗是重复了。首先cpu的实现方式相比wt的实现方式,毫无优势。如下是它们的对比:

    1. cpu和wt均是时间差计算出来的。
    2. cpu的时间精度为微秒,而wt的时间精度是纳秒。
    3. 每执行一个函数,函数消耗不足微秒时,cpu因精度关系,计算结果为0,导致失误增大,而wt计算结果会被正确地累计。

    mu内存消耗的理解,与wt基本一致。