4-记录一次optionRom卡死问题排查(图片不可见)

1. 概述

        xx项目中，UEFI的cli工具，可以实现与optionRom程序的通信。其中的一项功能是将事件日志dump出来。在dump日志的过程中，发现存在卡死的现象。添加多处打印进行问题的分析，发现卡死在了字符串打印的接口中。反复进行日志的打印，大概3小时左右可以复现问题

2. 问题排查

        在压力测试中存在卡死的问题，率先想到的就是存在内存越界或者陷入了某个死循环。当然了，经验问题有时候也会给人错误的指引。UEFI是单线程的程序，为了定位问题，只能根据第一次出现问题时候的日志，大致了解出现问题的代码位置，再添加打印进行问题的追踪。

2.1. 代码执行流程

        排查界面卡死的问题，率先将该指令的执行流程进行梳理，cli /c0 show termlog的执行流程如下所示：

 

        以上的流程图，大致绘制整个termlog show的执行流程，因为项目问题，不做细致的描述。其中的4、5、6步骤都进行了内存的申请于释放。

2.2. 出现问题的代码位置

        最开始出现问题的打印显示如下：

 

        只能在将内容进行dump的时候，出现了卡住，在使用sol获取的打印日志中看不到具体卡住的位置。为了确定问题出现的位置，将整个执行流程的代码中添加打印，进行问题的复现。

       在第二次问题复现时候，发现了程序卡住的位置：

 

      卡住的位置对应上文的394行。

2.3. 问题根因的定位

2.3.1. 问题分析

        看到函数卡在了gBS->output中，以为问题已经定位完成，仅仅需要看一下gBS->output中哪里出现的问题即可，但是很不幸，在开源的edk2中，并没有找到gBS->output赋值的位置，即使找到对个别全局变量赋值的位置，添加的打印也不会生效。

        经过一段时间的学习，可以确认这样的一个流程。Edk2是bios于UEFI公共的代码，edk2看作是看远的bios。OptionRom看作是bios代码的一个插件，但是这个插件中调用的一些底层接口，是在编译生成bios时候就固定好的，不是编译到optionRom程序中的。

        想到这里，突然恍然大悟，既然追到问题是卡在bios中，那应该看一下出现问题时候bios的打印。在bios的advance界面，按住ctrl+F11，可以显示隐藏开关。

        在放开bios打印的情况下，进行问题的复现，发现卡住的位置依旧是gBS->output中，查看出现问题的打印如下：

 

        有了这种打印信息，我们知道问题出现在bios里面。但是触发的原因是在BIOS中还是在optionRom的代码中，这个问题还不清楚，于是从两个方面进行问题的定位。从optionRom的代码出发，找可能出发问题的原因；从BIOS方向出发，找到出现问题的代码；

2.3.2.  optionRom中引起问题的代码

        在排查optionRom代码中问题的时候，最开始怀疑的是，存在代码的越界。于是在但凡用到malloc和free的接口处都加上了打印，以及防御机制。这里涉及了两个定位问题的技巧：

2.3.2.1. 使用宏定义替代原本的free函数

 

        使用新的宏代替原本的函数，多传入两个函数和行号的参数，这样可以在不改变其他代码的前提下，实现打印行号的功能。

        类似的方式也可以用到指令上，例如将shell下面的一个指令改名，自己手写一个sh文件代替这个指令程序，实现添加打印的效果。

2.3.2.2.  malloc和free函数封装头尾

        标准的malloc和free函数时候，是在堆空间上申请一段内存。在申请指定内存的前提下，还会多申请一段内存，作为malloc内存的header头结构体和tail结构体。头尾结构体中，根据系统不一样，存放的呢容也是不同的。以UEFI的代码为例，进行malloc申请于释放函数的位置是：

 

       头和尾指针中的内容，如下所示：

 

       为了模拟edk2中的数据结构，在optionRom程序中，字节封装一个malloc和free接口：

 

       有了这种函数的申请方式，一旦出现数据的越界，就能在optionRom的函数中显示，不会走到BIOS的代码中。

       当然做到这里，发现程序卡死的时候，不会走到optionRom程序的malloc和free函数中。说明导致卡死的原因不是越界。

2.3.2.3. 代码深度review

        我们在已经知道代码是卡死在标准输出函数的基础上，进行代码的review，看一下问题可能出现在哪里。在流程图的第4步，需要将从片内获取的二进制log信息，进行转换。这一步需要先读取16byte的数据，一次转成类似0x3e的形式。在判断是否将这个16Byte的数据，转换成为ASSIC的形式进行输出。这里存在一个问题，那就是ASSIC码的0-31和127号数据，是不可以输出显示的，属于控制字符。详细信息参考：

        https://www.sojson.com/ascii.html

        从卡住的位置，也可以看到，出现问题时候，总是有不可显示的字符存在：

 

       考虑到这点，我们尝试将不可显示的字符屏蔽掉。结果出任意料，问题不在发生。

2.3.3. bios中问题的定位

       仅仅从sol的打印信息中，是看不出来问题的。于是我们拉来了BIOS的同事，进行问题的协助定位。BISO同事进行问题定位的第一步，是查看BMC的日志，具体如下：

 

       根据复现问题的时候节点，可以在BMC中找到ASSERT的日志，存在紧急级别的日志，确实可以证明出现了ASSERT的问题。但是仅仅从BMC的日志中，不足以完全定位问题，于是用到了DCI工具，进行堆栈的显示。

       在intel G30机器上进行问题的复现。有如下的定位：

 

       可以看到最终的函数卡在了字符串高度和偏移的函数中（BIOS中），这个是由于我们输入了包含不可显示ASSIC码的原因。

3. 问题总结

        该问题花费了大量的时间进行定位，最终确定是BIOS中的标准输出函数会在打印不可显示ASSIC码字符时候，寻找字符偏移和位置错误，出现了卡住。由于代码在BISO中，UEFI组内看不到，问题不再继续追。总结一下该问题排查的收获。

（1）      排查问题，先梳理流程再层层划分

（2）      使用宏替换以及malloc添加头尾的方式，可以确认是否存在数据的越界

（3）      开启BIOS打印以及使用DCI工具，可以查看BIOS的堆栈信息

（4）      BMC的log日志可以进行问题的初步分析

（5）      optionRom中使用的大量开源库函数，在BIOS中编译

        当然在本次的bug追查中，UEFI组内也使用了gdb工具进行问题的分析，UEFI下gdb的使用，可以在以后进行总结