shirongqi/streamscanner

PHP版的console.log(),能在流程中调用一个函数，后台就能记录该调用该函数的详细信息包括：步骤数，类名，方法名，行号，上一步到这一步的运行时间等；

dev-master 2018-03-14 09:10 UTC

MIT

• shirongqi

README

#PHP 基于debug_backtrace的流程日志与日志分析#

我们都知道php测试性能有一个叫xhprof的(不知道也没事儿的确挺消耗性能的)，执行后能看到全部函数的调用关系图，但是我压根不知道xhprof这个东西咋跑，每每看到那个图我往往是一脸懵x...

奥这个函数被调用了N多次....then去查查哪里调用的，花了大半天....？！

每每开发时‘我’其实是知道流程的，其实我就想看看

• 我跑到哪里了
• 这一步和下一步的运行时间看看性能，看看接口反应速度
• 记录执行流程防止背锅...

而已，最后希望就像在程序里打console.log()一样,能尽量少传参或者不传参，直接执行一个方法就能获得当前的执行日志； 于是我们利用debug_backtrace生成的一个流程日志，只要在任意的流程中调用这PL::instance()->set()方法，记做一个采样点，在业务流程中有多个采样点的话，会形成一个流程日志方便监控整个流程的运行状况;

【依赖】PHP版本大于7.0

使用了一些P7新特性比如array改成了[]，list方法的改进，??的短路使用方式等等；

【非必须依赖】php安装apcu扩展

仅仅在开启了apcu缓存的时候才是必须的的

大并发环境下频繁访问磁盘对硬盘不友好，所以往往先存到了apcu共享缓存中，达到100条的时候才触发一次写磁盘的逻辑； 注意默认的触发方式为直接写磁盘，启用apcu缓存逻辑，请务必安装PHP的apcu扩展之后触发开关，开关在PL类之前定义：

define('APCU_SWITCH',true); // 目前代码中已定义为false，用的时候只要修改为true即可；

初始日志格式为：

采样点1&采样点2&采样点3&采样点4&... // 第一次流程	
调用处1&采样点&2采样点3&采样点4&... // 第二次流程	

其中采样点描述为：

callCount:调用次序|file:调用的文件|namespace:命名空间|function:调用方法|line:调用处的行号|time:调用发生的时间戳（微秒）|message:个人输入的信息（后面解释从哪输入的这个信息）；

关于日志格式为啥不是个JSON的问题，其实在日志录入的时候，考虑到其不是主业务但也会占用资源，要尽可能少的占用资源和快速的写日志，而json_encode方法比字符拼接较慢一些，于是只采用了字符串拼接的方式，只要日志分割的好，分析起来问题还是不大的，所以目前用了一行一行记录的日志格式；

获取数据

通过一个流程一个流程的输出一次流程-》记录到apcu-》记录到磁盘，于是我们得到了一个初始化的日志，日志最终存在于文件中，并且这个流程日志支持多个流程，默认的流程名为defaultLine，也可以设定子流程，关于子流程这个这个后面说，如果有多个流程的话日志是分开记录的;

数据分析

php业务是流程化的（我知道PHP有线程但是大型业务妥妥的不会用到，因为过多插件线程压根就不安全导致无法使用多线程），我们拿第一次流程来说，采样点2的时间减去采样点1的时间戳，会得到第1步到第2步的运行时间，之后可以沿着这个思路直到组后一个采样点，得到一个从哪一步到哪一步的一个运行时间，所以这个日志还是有很多东西可以分析的，目前的策略是弄一个定时任务，发现有data结尾的数据文件，立刻删掉源文件（每次落盘的时候还是会自动生成.data文件的）按行进行分析，分析后的数据直接附加（append）到.parse结尾的文件中去；

set方法和子流程

PL::instance()->set(string $lineName = false, string $message = false)

流程名

第一个参数为子流程名，一个大的流程中可以由更多的小流程组成，如果你有几组流程的话可以设置不同的子流程名，放心，各个流程都是各自独立的，包括最后的数据文件也是独立存放的有利于数据分析，，如果流程名为布尔值的false，代表使用默认的流程名也就是defaultLine，否则将使用你自定义的流程名；

日志信息

第二个参数为采样点的记录信息说明，也就是上面采样点描述中message字段对应的值，可以自己写点啥方便记忆和理解流程，但最好别太长,也不能包括|和&这两个符号，否则影响日志分析，毕竟日志是靠|和&进行分割的；

registerLines方法

一段代码可能会是多个流程的复用，可能里面会有很多采样点，有你的，有我的，当然还有他的，但是我只想记录我的流程，第一，先打开一个叫LINES_FILTER_CONTROLLER的开关：

define('LINES_FILTER_CONTROLLER', false);       

平常是false代表关闭着着的，表示所有流程都会被记录下来，如果值为true则代表会对采样点过滤，在调用流程控制之前要先注册到底要监控哪几个流程，使用到了这个方法：

PL::instance()->registerLines(array $input);

输入举例：

$input = array(
		PL::DEFAULTLINENAME=>false,     // 关闭主线，默认是存在且打开的，这个值就是defaultLine；
		'line2' => true,                // 打开line2线，表示记录命名为line2的采样点，其余没提到的或者false的，都忽略；
		'line3' => false,               // 关闭line3线，当然你不写也没问题，line3线照样是关闭的；

);
PL::instance()->registerLines($input);

###日志输出### 其实，日志我是按照天来输出的，并没有太大的策略，在StreamScanner.php平级目录下建立data目录，并赋予0777权限（你懂得...），会主动在这个目录下创建一个日期目录比如20161129，在这个目录下会创建出流程个数的流程日志，假如说我命名了两个流程，一个是默认的流程defaultLine，另一个line2，则会在这个地方生成两个文件defaultLine.data和line2.data；

###日志分析###

拿到原始日志，尝试进行了一次分析，文件所在目录直接执行php parseData.php ，会将data目录下日期文件夹下所有的data结尾的文件进行一次分析并得到.parse结尾的文件，比如上面的文件将命名为defaultLine.data.parse和line2.data.parse;

分析后的日志格式为：

（初始时间戳::调用次序:命名空间:方法名:行号）--到第二步的运行时间（百分比）--（调用次序:命名空间:方法名:行号）--...（调用次序:命名空间:方法名:行号::总耗时）

举例如下：

（初始时间戳::调用次序:命名空间:方法名:行号）--到第2步的运行时间（百分比）--（调用次序:命名空间:方法名:行号::总耗时）
(1480473080::1:AAA:test:13)---0.0003(59.99%)>>>(2:BBB:test:24)---0.0002(40.01%)>>>(3:BBB:test:26::0.0005)
(1480473080::1:AAA:test:13)---0.0003(74.97%)>>>(2:BBB:test:24)---0.0001(25.03%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(74.97%)>>>(2:BBB:test:24)---0.0001(25.03%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(60.04%)>>>(2:BBB:test:24)---0.0002(39.96%)>>>(3:BBB:test:26::0.0005)
(1480473080::1:AAA:test:13)---0.0003(75.01%)>>>(2:BBB:test:24)---0.0001(24.99%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(74.97%)>>>(2:BBB:test:24)---0.0001(25.03%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(74.97%)>>>(2:BBB:test:24)---0.0001(25.03%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(74.97%)>>>(2:BBB:test:24)---0.0001(25.03%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(75.01%)>>>(2:BBB:test:24)---0.0001(24.99%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(75.01%)>>>(2:BBB:test:24)---0.0001(24.99%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(75.01%)>>>(2:BBB:test:24)---0.0001(24.99%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(75.03%)>>>(2:BBB:test:24)---0.0001(24.97%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(59.99%)>>>(2:BBB:test:24)---0.0002(40.01%)>>>(3:BBB:test:26::0.0005)
(1480473080::1:AAA:test:13)---0.0003(75.03%)>>>(2:BBB:test:24)---0.0001(24.97%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(75.01%)>>>(2:BBB:test:24)---0.0001(24.99%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0003(75.01%)>>>(2:BBB:test:24)---0.0001(24.99%)>>>(3:BBB:test:26::0.0004)
(1480473080::1:AAA:test:13)---0.0002(49.97%)>>>(2:BBB:test:24)---0.0002(50.03%)>>>(3:BBB:test:26::0.0004)
(1480473081::1:AAA:test:13)---0.0003(75.03%)>>>(2:BBB:test:24)---0.0001(24.97%)>>>(3:BBB:test:26::0.0004)
(1480473081::1:AAA:test:13)---0.0003(74.97%)>>>(2:BBB:test:24)---0.0001(25.03%)>>>(3:BBB:test:26::0.0004)
(1480473081::1:AAA:test:13)---0.0003(74.97%)>>>(2:BBB:test:24)---0.0001(25.03%)>>>(3:BBB:test:26::0.0004)
(1480473081::1:AAA:test:13)---0.0003(75.03%)>>>(2:BBB:test:24)---0.0001(24.97%)>>>(3:BBB:test:26::0.0004)
(1480473081::1:AAA:test:13)---0.0003(74.97%)>>>(2:BBB:test:24)---0.0001(25.03%)>>>(3:BBB:test:26::0.0004)
(1480473081::1:AAA:test:13)---0.0003(74.97%)>>>(2:BBB:test:24)---0.0001(25.03%)>>>(3:BBB:test:26::0.0004)