UPDATE: 2018.4.4
笔者将考虑将这一模块封装成一个完整的java第三方包并可能进行开源放送,完成后将会再次发布最新消息,敬请期待。
-------------------------分割线-------------------------
也许本文的标题你们没咋看懂。但是,本文将带大家领略输出调试的威力。
说到灵感,其实是源于笔者在修复服务器的ssh
故障时的一个发现。
这个学期初,同袍(容我来一波广告产品页面,同袍官网)原服务器出现硬件故障,于是笔者连夜更换新服务器,然而在配置ssh
的时候遇到了不明原因的连接失败。于是笔者百度了一番,发现了一些有趣的东西。
首先打开ssh
的配置文件
sudo nano /etc/ssh/sshd_config
我们可以发现里面有这么几行
# Logging
LogLevel DEBUG3
这个是做什么的呢?我们再去看看ssh
的日志文件。
sudo nano /var/log/auth.log
内容如下
Apr 3 01:39:31 tp sshd[29439]: debug2: channel 180: read<=0 rfd 190 len 0
Apr 3 01:39:31 tp sshd[29439]: debug2: channel 180: read failed
Apr 3 01:39:31 tp sshd[29439]: debug2: channel 180: close_read
Apr 3 01:39:31 tp sshd[29439]: debug2: channel 180: input open -> drain
Apr 3 01:39:31 tp sshd[29439]: debug2: channel 180: ibuf empty
Apr 3 01:39:31 tp sshd[29439]: debug2: channel 180: send eof
Apr 3 01:39:31 tp sshd[29439]: debug3: send packet: type 96
Apr 3 01:39:31 tp sshd[29439]: debug2: channel 180: input drain -> closed
Apr 3 01:39:31 tp sshd[29439]: debug1: Connection to port 4096 forwarding to 0.0.0.0 port 0 requested.
Apr 3 01:39:31 tp sshd[29439]: debug2: fd 122 setting TCP_NODELAY
Apr 3 01:39:31 tp sshd[29439]: debug2: fd 122 setting O_NONBLOCK
Apr 3 01:39:31 tp sshd[29439]: debug3: fd 122 is O_NONBLOCK
Apr 3 01:39:31 tp sshd[29439]: debug1: channel 112: new [forwarded-tcpip]
Apr 3 01:39:31 tp sshd[29439]: debug3: send packet: type 90
Apr 3 01:39:31 tp sshd[29439]: debug3: receive packet: type 91
Apr 3 01:39:31 tp sshd[29439]: debug2: channel 112: open confirm rwindow 2097152 rmax 32768
可以很明显的看到debug1
、debug2
、debug3
三个关键词。而当笔者将上面的LogLevel
改成了DEBUG1
后,debug2
、debug3
的日志信息就都不再被记录。
在ssh中,Loglevel
决定了日志文件中究竟显示什么样粒度的debug信息。
于是笔者灵机一动,要是这样的模式,运用于Java工程的调试,会怎么样呢?
以OO2018第三次作业为例。
笔者在运行时不给程序添加命令行(默认不开启任何DEBUG信息),然后输入数据(绿色字为输入数据),输出如下:
笔者在运行时给程序添加了命令行--debug 1
(开启一级DEBUG信息),然后输入数据,输出如下:
笔者在运行时给程序添加了命令行--debug 3
(开启三级DEBUG信息),然后输入数据,输出如下:
笔者在运行时给程序添加了命令行--debug 3 --debug_show_location
(开启三级DEBUG信息并展示DEBUG位置),然后输入数据,输出如下:
笔者在运行时给程序添加了命令行--debug 4 --debug_show_location --debug_package_name "models.lift"
(开启四级DEBUG信息并展示DEBUG位置,并限定只输出models.lift
包内的信息),然后输入数据,输出如下:
笔者在运行时给程序添加了命令行--debug 3 --debug_show_location --debug_class_name "Scheduler" --debug_include_children
(开启四级DEBUG信息并展示DEBUG位置,并限定只输出Scheduler
类和其相关子调用内的信息),然后输入数据,输出如下:
可以看到,笔者在自己的程序中也实现了一个类似的可调级别和范围的debug信息系统。
源码如下(附带简要的命令行使用说明,Argument类为笔者自己封装的命令行参数管理类,如需要使用请自行封装):
package helpers.application;
import configs.ApplicationConfig;
import exceptions.application.InvalidDebugLevel;
import exceptions.application.arguments.InvalidArgumentInfo;
import models.application.Arguments;
import models.application.HashDefaultMap;
import java.util.regex.Pattern;
/**
* debug信息输出帮助类
* 使用说明:
* -D <level>, --debug <level> 设置输出debug信息的最大级别
* --debug_show_location 输出debug信息输出位置的文件名和行号
* --debug_package_name <package_name> 限定输出debug信息的包名(完整包名,支持正则表达式)
* --debug_file_name <file_name> 限定输出debug信息的文件名(无路径,支持正则表达式)
* --debug_class_name <class_name> 限定输出debug信息的类名(不包含包名的类名,支持正则表达式)
* --debug_method_name <method_name> 限定输出的debug信息的方法名(支持正则表达式)
* --debug_include_children 输出限定范围内的所有子调用的debug信息(不加此命令时仅输出限定范围内当前层的debug信息)
*/
public abstract class DebugHelper {
/**
* debug level
*/
private static int debug_level = ApplicationConfig.getDefaultDebugLevel();
/**
* show debug location
*/
private static boolean show_debug_location = false;
private static boolean range_include_children = false;
/**
* 范围限制参数
*/
private static String package_name_regex = null;
private static String file_name_regex = null;
private static String class_name_regex = null;
private static String method_name_regex = null;
/**
* 设置debug level
*
* @param debug_level 新的debug level
* @throws InvalidDebugLevel 非法的debug level抛出异常
*/
private static void setDebugLevel(int debug_level) throws InvalidDebugLevel {
if ((debug_level <= ApplicationConfig.getMaxDebugLevel()) && (debug_level >= ApplicationConfig.getMinDebugLevel())) {
DebugHelper.debug_level = debug_level;
} else {
throw new InvalidDebugLevel(debug_level);
}
}
/**
* 设置show debug location
*
* @param show_debug_location show_debug_location
*/
private static void setShowDebugLocation(boolean show_debug_location) {
DebugHelper.show_debug_location = show_debug_location;
}
/**
* 设置debug信息输出范围是否包含子调用
*
* @param include_children 是否包含子调用
*/
private static void setRangeIncludeChildren(boolean include_children) {
range_include_children = include_children;
}
/**
* 设置包名正则筛选
*
* @param regex 正则表达式
*/
private static void setPackageNameRegex(String regex) {
package_name_regex = regex;
}
/**
* 设置文件名正则筛选
*
* @param regex 正则表达式
*/
private static void setFileNameRegex(String regex) {
file_name_regex = regex;
}
/**
* 设置类名正则筛选
*
* @param regex 正则表达式
*/
private static void setClassNameRegex(String regex) {
class_name_regex = regex;
}
/**
* 设置方法正则筛选
*
* @param regex 正则表达式
*/
private static void setMethodNameRegex(String regex) {
method_name_regex = regex;
}
/**
* 命令行参数常数
*/
private static final String ARG_SHORT_DEBUG = "D";
private static final String ARG_FULL_DEBUG = "debug";
private static final String ARG_FULL_DEBUG_SHOW_LOCATION = "debug_show_location";
private static final String ARG_FULL_DEBUG_INCLUDE_CHILDREN = "debug_include_children";
private static final String ARG_FULL_DEBUG_PACKAGE_NAME = "debug_package_name";
private static final String ARG_FULL_DEBUG_FILE_NAME = "debug_file_name";
private static final String ARG_FULL_DEBUG_CLASS_NAME = "debug_class_name";
private static final String ARG_FULL_DEBUG_METHOD_NAME = "debug_method_name";
/**
* 为程序命令行添加相关的读取参数
*
* @param arguments 命令行对象
* @return 添加完读取参数的命令行对象
* @throws InvalidArgumentInfo 非法命令行异常
*/
public static Arguments setArguments(Arguments arguments) throws InvalidArgumentInfo {
arguments.addArgs(ARG_SHORT_DEBUG, ARG_FULL_DEBUG, true, String.valueOf(ApplicationConfig.getDefaultDebugLevel()));
arguments.addArgs(null, ARG_FULL_DEBUG_SHOW_LOCATION, false);
arguments.addArgs(null, ARG_FULL_DEBUG_INCLUDE_CHILDREN, false);
arguments.addArgs(null, ARG_FULL_DEBUG_PACKAGE_NAME, true);
arguments.addArgs(null, ARG_FULL_DEBUG_FILE_NAME, true);
arguments.addArgs(null, ARG_FULL_DEBUG_CLASS_NAME, true);
arguments.addArgs(null, ARG_FULL_DEBUG_METHOD_NAME, true);
return arguments;
}
/**
* 根据程序命令行进行DebugHelper初始化
*
* @param arguments 程序命令行参数解析结果
* @throws InvalidDebugLevel DebugLevel非法
*/
public static void setSettingsFromArguments(HashDefaultMap<String, String> arguments) throws InvalidDebugLevel {
DebugHelper.setDebugLevel(Integer.valueOf(arguments.get(ARG_FULL_DEBUG)));
DebugHelper.setShowDebugLocation(arguments.containsKey(ARG_FULL_DEBUG_SHOW_LOCATION));
DebugHelper.setRangeIncludeChildren(arguments.containsKey(ARG_FULL_DEBUG_INCLUDE_CHILDREN));
DebugHelper.setPackageNameRegex(arguments.get(ARG_FULL_DEBUG_PACKAGE_NAME));
DebugHelper.setFileNameRegex(arguments.get(ARG_FULL_DEBUG_FILE_NAME));
DebugHelper.setClassNameRegex(arguments.get(ARG_FULL_DEBUG_CLASS_NAME));
DebugHelper.setMethodNameRegex(arguments.get(ARG_FULL_DEBUG_METHOD_NAME));
}
/**
* 判断debug level是否需要打印
*
* @param debug_level debug level
* @return 是否需要打印
*/
private static boolean isLevelValid(int debug_level) {
return ((debug_level <= DebugHelper.debug_level) && (debug_level != ApplicationConfig.getNoDebugLevel()));
}
/**
* 判断栈信息是否合法
*
* @param trace 栈信息
* @return 栈信息是否合法
*/
private static boolean isTraceValid(StackTraceElement trace) {
try {
Class cls = Class.forName(trace.getClassName());
String package_name = (cls.getPackage() != null) ? cls.getPackage().getName() : "";
boolean package_name_mismatch = ((package_name_regex != null) && (!Pattern.matches(package_name_regex, package_name)));
boolean file_name_mismatch = ((file_name_regex != null) && (!Pattern.matches(file_name_regex, trace.getFileName())));
boolean class_name_mismatch = ((class_name_regex != null) && (!Pattern.matches(class_name_regex, cls.getSimpleName())));
boolean method_name_mismatch = ((method_name_regex != null) && (!Pattern.matches(method_name_regex, trace.getMethodName())));
return !(package_name_mismatch || file_name_mismatch || class_name_mismatch || method_name_mismatch);
} catch (ClassNotFoundException e) {
return false;
}
}
/**
* 判断栈范围是否合法
*
* @return 栈范围是否合法
*/
private static boolean isStackValid(StackTraceElement[] trace_list) {
for (int i = 1; i < trace_list.length; i++) {
StackTraceElement trace = trace_list[i];
if (isTraceValid(trace)) return true;
}
return false;
}
/**
* 判断限制范围是否合法
*
* @return 限制范围是否合法
*/
private static boolean isRangeValid(StackTraceElement[] trace_list, StackTraceElement trace) {
if (range_include_children)
return isStackValid(trace_list);
else
return isTraceValid(trace);
}
/**
* debug信息输出
*
* @param debug_level debug level
* @param debug_info debug信息
*/
public static void debugPrintln(int debug_level, String debug_info) {
if (isLevelValid(debug_level)) {
StackTraceElement[] trace_list = new Throwable().getStackTrace();
StackTraceElement trace = trace_list[1];
if (isRangeValid(trace_list, trace)) {
String debug_location = String.format("[%s : %s]", trace.getFileName(), trace.getLineNumber());
System.out.println(String.format("[DEBUG - %s] %s %s",
debug_level, show_debug_location ? debug_location : "", debug_info));
}
}
}
}
在一开始做好基本的配置后(命令行解析程序请自行编写),调用起来也是非常简单:
DebugHelper.debugPrintln(2, String.format("Operation request %s pushed in.", operation_request.toString()));
静态方法debugPrintln
的第一个参数表示debug level,这也将决定在当前debug级别下是否输出这一debug信息。而第二个参数则表示debug信息。
说了这些,那么这一系统如何进行实际运用呢?
笔者的程序中,最大的debug level是4
,在关键位置上近乎每几行语句就会输出相应的调试信息,展示相关计算细节。而且使用--debug_show_location
命令行时还可以显示debug信息打印方法的调用位置。
而一般的bug无非是几种情况:
--debug_show_location
参数就可以相当精确地定位到crash的位置。简单来说,在上面的效果展示图中我们可以看到,只要开启--debug_show_location
就可以查看debug信息打印的代码位置。例如,笔者程序中(文件Scheduler.java
中)有这么一块:
可以看到在上面的--debug 3 --debug_show_location
图中,就有Scheduler.java : 59
的输出信息。
当我们在debug的时候,先是根据输出的信息判断是哪一步的debug信息开始出现错误,然后就可以根据debug信息中提供的位置来将bug位置缩小到一个很小的范围。(例如:Scheduler.java : 59
的输出还是正确的,到了Scheduler.java : 70
这一行就出现了错误,那么可以基本确定bug就在Scheduler.java
的60
-70
行之间)。
说到这里,问题来了,究竟如何合理高效地布置debug信息的输出呢?
很显然,过少的输出根本无助于编程者快速的找到问题;而过多的信息则会导致有用的没用的全混在一起,也一样无助于编程者解决bug。
目前笔者还是在手动添加输出点。
笔者根据自己对于自己程序的模块化了解,例如:
则我们可以按照如上的标准,在各个关键位置上进行debug信息输出。
例如,对于程序(程序仅做演示):
public static void main(String[] args) {
try {
initialize(args);
// initialize the standard input
Scanner sc = new Scanner(System.in);
// check if there an available line in the standard input
if (!sc.hasNextLine()) {
throw new Exception("No available line detected!");
}
// get a line from the standard input
String line = sc.nextLine();
// initialize the regular expression objects
Pattern pattern = Pattern.compile("(\\+|-|)\\d+(\\.\\d+)?");
Matcher matcher = pattern.matcher(line);
// get the numbers from the input line
ArrayList<Double> array = new ArrayList<>();
while (matcher.find()) {
array.add(Double.parseDouble(matcher.group(0)));
}
// if there is no value in the string
if (array.size() == 0) {
throw new Exception(String.format("No value detected in input - \"%s\".", line));
}
// calculate the average value of the array
double average = 0;
for (double value : array) {
average += value;
}
average /= array.size();
// calculate the variance value of the array
double variance = 0;
for (double value : array) {
variance += Math.pow((value - average), 2.0);
}
variance /= array.size();
// output the result;
System.out.println(String.format("Variance : %.2f", variance));
} catch (Exception e) { // exception detected
System.out.println(String.format("[ERROR - %s] %s", e.getClass().getName(), e.getMessage()));
System.exit(1);
}
}
这是一个简单的demo,用途是从字符串中抽取数,并计算方差。运行效果如下:
我们来分析一下程序。首先,很明显,程序的结构分为如下几个部分:
我们可以按照这几个基本模块,来设置level 1
的debug信息输出,就像这样:
public static void main(String[] args) {
try {
initialize(args);
// initialize the standard input
Scanner sc = new Scanner(System.in);
// check if there an available line in the standard input
if (!sc.hasNextLine()) {
throw new Exception("No available line detected!");
}
// get a line from the standard input
String line = sc.nextLine();
DebugHelper.debugPrintln(1, String.format("Line detected : \"%s\"", line));
// initialize the regular expression objects
Pattern pattern = Pattern.compile("(\\+|-|)\\d+(\\.\\d+)?");
Matcher matcher = pattern.matcher(line);
// get the numbers from the input line
ArrayList<Double> array = new ArrayList<>();
while (matcher.find()) {
array.add(Double.parseDouble(matcher.group(0)));
}
DebugHelper.debugPrintln(1,
String.format("Array detected : [%s]",
String.join(", ",
array
.stream()
.map(number -> number.toString())
.collect(Collectors.toList())
)
)
);
// if there is no value in the string
if (array.size() == 0) {
throw new Exception(String.format("No value detected in input - \"%s\".", line));
}
// calculate the average value of the array
double average = 0;
for (double value : array) {
average += value;
}
average /= array.size();
DebugHelper.debugPrintln(1, String.format("Average value : %s", average));
// calculate the variance value of the array
double variance = 0;
for (double value : array) {
variance += Math.pow((value - average), 2.0);
}
variance /= array.size();
DebugHelper.debugPrintln(1, String.format("Variance value : %s", variance));
// output the result;
System.out.println(String.format("Variance : %.2f", variance));
} catch (Exception e) { // exception detected
System.out.println(String.format("[ERROR - %s] %s", e.getClass().getName(), e.getMessage()));
System.exit(1);
}
}
然后我们将--debug
参数设置为1
,输出如下:
如果接下来,在这里面发现有不对(如果真的能的话)。
我们首先可以想到,最有可能出现错误的就是计算密集的平均值和方差计算部分。想进一步排查的话,可以在其计算循环内添加level 2
的debug信息输出:
public static void main(String[] args) {
try {
initialize(args);
// initialize the standard input
Scanner sc = new Scanner(System.in);
// check if there an available line in the standard input
if (!sc.hasNextLine()) {
throw new Exception("No available line detected!");
}
// get a line from the standard input
String line = sc.nextLine();
DebugHelper.debugPrintln(1, String.format("Line detected : \"%s\"", line));
// initialize the regular expression objects
Pattern pattern = Pattern.compile("(\\+|-|)\\d+(\\.\\d+)?");
Matcher matcher = pattern.matcher(line);
// get the numbers from the input line
ArrayList<Double> array = new ArrayList<>();
while (matcher.find()) {
array.add(Double.parseDouble(matcher.group(0)));
}
DebugHelper.debugPrintln(1,
String.format("Array detected : [%s]",
String.join(", ",
array
.stream()
.map(number -> number.toString())
.collect(Collectors.toList())
)
)
);
// if there is no value in the string
if (array.size() == 0) {
throw new Exception(String.format("No value detected in input - \"%s\".", line));
}
// calculate the average value of the array
double average = 0;
for (double value : array) {
average += value;
DebugHelper.debugPrintln(2, String.format("present number : %s, present sum : %s", value, average));
}
average /= array.size();
DebugHelper.debugPrintln(1, String.format("Average value : %s", average));
// calculate the variance value of the array
double variance = 0;
for (double value : array) {
variance += Math.pow((value - average), 2.0);
DebugHelper.debugPrintln(2, String.format("present number : %s, present part : %s", value, variance));
}
variance /= array.size();
DebugHelper.debugPrintln(1, String.format("Variance value : %s", variance));
// output the result;
System.out.println(String.format("Variance : %.2f", variance));
} catch (Exception e) { // exception detected
System.out.println(String.format("[ERROR - %s] %s", e.getClass().getName(), e.getMessage()));
System.exit(1);
}
}
然后我们将--debug
参数设置为2
,输出如下:
可以看到连每一次的计算步骤也都显示了出来。然而,如果我们修复了一个局部区域的level 2
bug,然后需要暂时关闭level 2
信息的输出的话,是不是需要删除level 2
输出呢?
不需要!直接将命令行改回--debug 1
即可。
综上,demo虽然略简单了些,但是大致就是这样一个部署输出点的过程:
说到一种比较易于实现的傻瓜化部署方式,当然是在所有函数入口的时候输出参数值信息,并且在出口处输出返回值信息。
这样的做法优点很明显:
不过缺点也一样很明显:
public abstract class Main {
public static void main(String[] args) {
/*
do somthing inside
about 1,000+ lines
*/
}
}
如果只在出入口进行输出的话,则可以说是毫无意义的。
int
、double
、String
等;有的展示稍微麻烦,但是还算可以展示,例如ArrayList
、HashMap
等;而有些对象则是非常复杂且难以展示的,例如线程对象、DOM元素、网络协议配置对象等。不仅如此,就算都能展示,要是输入数据是一个极其庞大的HashMap
(比如有数十万条的key),如果盲目的一口气输出来的话,不仅会给debug信息的展示效果带来很大的干扰,而且如此大量的IO还会令本就不充裕的IO资源雪上加霜(在这个算法已经相当发达的时代,IO往往是程序性能的主要瓶颈),而反过来想想,想发掘出究竟哪些是有效信息,似乎又不那么容易做到。显然,这样一个傻瓜化的策略,还需要很多的改进才可能趋于成熟。
笔者之前稍微了解过一些语法树相关的概念。实际上,基于编译器的语法树常常被用于代码查重,甚至稍微高级一点的代码混淆技巧也难以幸免(以C++为例,#define
、拆分函数等一般的混淆技术在基于语法树的代码查重面前已经难以蒙混过关)。
笔者对编译原理等一些更细的底层原理实际上并不是很了解,只是对此类东西有一些感性的认识。笔者在想,既然语法树具有这样的特性,那么能不能基于编译器语法树所提供的程序结构信息,结合Javadoc API提供的方法接口信息,来进行更加准确有效一些的debug信息输出点自动部署呢?(甚至,如果条件允许的话,可以考虑收集一些用户数据再使用RNN进行有监督学习,可能效果会更贴近实际)
如上文所述,笔者目前是根据自己的程序采用层层细化的方式来手动部署debug信息输出。
所以笔者在debug level的手动设定问题上基本也在遵循层层细化的原则。此处不再赘述。
目前笔者想到的一种较为可行的debug level自动生成策略,是根据方法之间的依存关系。
我们可以以函数入口点方法(笔者的程序中一般为Main.main
)为根节点,再基于语法树(或者实在不行手写一个基于文本的文法分析也行)分析出根节点方法中调用的其他方法来作为子节点。以此类推构建起来一棵树(同时可能需要处理拓扑结构上的环等结构)。然后结合包、类图信息等的分析进行一些调整,最终建立起完整的树,之后再对于整个树的层次结构采用聚类等方式进行debug level的分类。
当然,这一切目前还只是停留在构想阶段,真正的实施,还有很长的路要走。Keep hungry!
综上,这一系统的主要优点如下:
笔者在本次作业中,debug全程使用这一系统,配合文本搜索工具(即便是linux cli下也是可以使用grep
的),定位一个bug的位置平均只需要一分钟不到,调试效率可以说超过了很多使用debugger的使用者。
事实证明,输出调试也是可以发挥出巨大威力的。
还是那句老话,以人为本。适合自己,适合团队,能提高效率创造效益的,就是最好的。