【都是函数嵌套惹的祸】一个9G的日志文件是怎么形成的?

本文由Markdown语法编辑器编辑完成。

1.背景:

近日在处理一个线上故障时，发现一个我负责的组件，在一段时间里面占用的内存突然飙升很多，通过grafana的面板中的内存占用，可以看到这条紫色的线，在12:30 ~ 13:50这段时间里面，内存占用的比例，从15%一直爬升到了72.5%，导致整台服务器的内存吃紧，无法正常工作。而这段时间，也使得文本日志的大小，一下从平时的几十M, 暴涨至9G多。

后来同事通过远程，临时重启了这个服务后，内存才降低下来，同时报告了这个故障。

接下来便是对该故障的分析。后来发现，其实是自己之前写的一个函数嵌套引起的，具体的排查过程如下.

2. 问题排查与解决:

遇到服务的故障时，首先就是要去查看这段时间内的容器日志. 那么进入容器日志后，可以看到在这段时间内，日志一直在快速地输出一些报错，报错的截图大致如下:

这段函数的主要作用是在将一个经过一些修改后的dicom的图像，另存在另一个文件名下面。
结果由于这个dicom文件，有一些私有标签，如报错中的tag (f830, f830), 里面的字符内容存在一些异常，导致在保存图像的时候，pydicom报了异常。

from loguru import logger
from pydicom.dataelem import RawDataElement, DataElement_from_raw

def save_modify_ds(
    ds: pydicom.dataset.Dataset,
    save_path,
    origin_pixel_representation=None,
    write_like_original=True,
):
    """存储单张dcm,自动去除非法tag.
    Args:
        ds (pydicom.dataset.Dataset): 待保存dataset
        save_path (str): 保存路径
        write_like_original (bool, optional): 当数据输入为bytes时,存储时是否自动增加dicom头  . Defaults to True.
    """
    series_iuid = ds.SeriesInstanceUID
    sop_iuid = ds.SOPInstanceUID
	try:
        ds.save_as(save_path, write_like_original=write_like_original)
    except KeyError as ke:
        p1 = re.compile(r"[(](.*?)[)]", re.S)
        unknown_key = re.findall(p1, ke.__str__())[0].split(",")
        unknown_tag = f"0x{unknown_key[0].strip()}{unknown_key[1].strip()}"
        ds.pop(unknown_tag)
        save_modify_ds(ds, save_path, write_like_original, has_repaired=True)
    except TypeError as te:
        # IS 类型 tag 检查
        for element in ds.elements():
        	if isinstance(element, RawDataElement):
        		try:
        			DataElement_from_raw(element)
        		except Exception:
                    ds.pop(element.tag)
            save_modify_ds(ds, save_path, write_like_original, has_repaired=True)

这段函数的本意，其实是在保存修改过的dicom图像时，增加了两个异常判断。
一个是KeyError的异常，一个是TypeError的异常。

针对这两类异常，都增加了一些容错机制。

如果发生KeyError的异常,

        p1 = re.compile(r"[(](.*?)[)]", re.S)
        unknown_key = re.findall(p1, ke.__str__())[0].split(",")
        unknown_tag = f"0x{unknown_key[0].strip()}{unknown_key[1].strip()}"
        ds.pop(unknown_tag)
        save_modify_ds(ds, save_path, write_like_original)

则从KeyError的错误信息中，通过正则的方式，希望匹配到报错的那个tag。然后一般报错的tag, 可能都是数值不规范引起的保存异常。这个时候，就通过提取出的tag的位置，将该tag从dataset中pop掉之后，再尝试保存该图像。

如果发生TypeError的异常，

        # IS 类型 tag 检查
        for element in ds.elements():
        	if isinstance(element, RawDataElement):
        		try:
        			DataElement_from_raw(element)
        		except Exception:
                    ds.pop(element.tag)
        save_modify_ds(ds, save_path, write_like_original)

则通过遍历dataset中的所有tag, 并且依次判断这些tag是否都是合法的tag. 如果有异常的tag, 也是采取pop的方式将之丢弃。丢弃异常tag后，再次尝试调用save_modify_ds()的方法。

本质上，就是通过嵌套调用的方式，将有问题的tag, 人工给它pop掉后，再尝试保存。

但在实际的应用中，这里的嵌套却导致了无限循环。也就是说，虽然在保存图像时，抛出了TypeError的异常，但是给出的修复方法却未奏效。导致再次调用save_modify_ds()的时候，仍然受困于TypeError, 而导致了无限循环。

3. 问题解决:

为了解决这个无限循环引起的内存暴涨的问题，当时想到的解决方案是:
如果遇到了这类的异常，最多只嵌套一次。如果第一次尝试修复异常图像受阻后，就直接将原始的图像，再另存一下。总好比，一直困在那里，无法从嵌套中跳出来，导致程序一直暴涨要好吧。

from loguru import logger
from pydicom.dataelem import RawDataElement, DataElement_from_raw
import traceback

def save_modify_ds(
    ds: pydicom.dataset.Dataset,
    save_path,
    origin_pixel_representation=None,
    write_like_original=True,
    has_repaired=False,
):
    """存储单张dcm
    Args:
        ds (pydicom.dataset.Dataset): 待保存dataset
        save_path (str): 保存路径
        write_like_original (bool, optional): 当数据输入为bytes时,存储时是否自动增加dicom头  . Defaults to True.
        has_repaired: 数据是否已经被修复后，再次尝试保存. 如果图像已经经过修复，保存图像时，仍然报异常，则直接抛出异常.
    """
    series_iuid = ds.SeriesInstanceUID
    sop_iuid = ds.SOPInstanceUID
    try:
        ds.save_as(save_path, write_like_original=write_like_original)
    except KeyError as ke:
        if has_repaired:
            raw_dataset = get_instance(series_iuid, sop_iuid)
            if raw_dataset:
                raw_dataset.save_as(save_path, write_like_original=write_like_original)
            else:
                raise Exception(f"序列: {series_iuid}, 图像: {sop_iuid}, 处理后的图像已经经过修复仍然保存报错, 无法处理!")
        else:
            logger.warning(f"图像未经过修复,保存图像异常,异常原因为:{traceback.format_exc()}")
            p1 = re.compile(r"[(](.*?)[)]", re.S)
            unknown_key = re.findall(p1, ke.__str__())[0].split(",")
            unknown_tag = f"0x{unknown_key[0].strip()}{unknown_key[1].strip()}"
            ds.pop(unknown_tag)
            save_modify_ds(ds, save_path, write_like_original, has_repaired=True)
    except TypeError as te:
        if has_repaired:
            raw_dataset = get_instance(series_iuid, sop_iuid)
            if raw_dataset:
                raw_dataset.save_as(save_path, write_like_original=write_like_original)
                logger.warning(f"序列: {series_iuid}, 图像: {sop_iuid}, 处理后的图像已经经过修复仍然保存报错, 保存原图.")
            else:
                raise Exception(f"序列: {series_iuid}, 图像: {sop_iuid}, 处理后的图像已经经过修复仍然保存报错, 无法处理!")
        else:
            logger.warning(f"图像未经过修复,保存图像异常,异常原因为:{traceback.format_exc()}")
            # IS 类型 tag 检查
            for element in ds.elements():
                if isinstance(element, RawDataElement):
                    try:
                        DataElement_from_raw(element)
                    except Exception:
                        ds.pop(element.tag)
            save_modify_ds(ds, save_path, write_like_original, has_repaired=True)

查看代码，在save_modify_ds()中，最后增加了一个参数叫: has_repaired, 是说这个图像，在第一次遇到保存图像发生异常后，是否已经经过了修复操作。
如果已经经过了修复，递归调用save_modify_ds()尝试保存图像。如果仍然进入Exception分支，就保存原图了，不再尝试修复了，避免陷入无限循环的被动境地。