记一次多线程奇怪的现象

做了一个数据交换的程序,程序中使用JAXB来进行xml文档的解析,上级要求程序可以配置解析的线程数量,以在高峰值的时候提高解析速度——此为背景说明。
某天,测试跑来和我说,你这程序的处理效率太低了,单线程1分钟才处理了120条数据,增加了10条线程,也就是130条,处理能力没有明显的提升,这样不行啊。


处理速度慢

我就很奇怪了,第一个反应是是不是代码敲错了多线程没有启动,还是单线程在跑。又或者有哪个方法是同步的造成了线程的等待。

对于第一种猜测,我在运行时增加了日志,在一些节点上增加了Thread.sleep(),通过日志判断确实是有多个线程在运行解析任务,排除这个原因。
对于第二种猜测,在log的基础上查看各个方法的用时。发现了一个很奇怪的现象。用JAXB把string类型的xml文档转成对应的pojo,这个方法在只有1个线程的情况下只要30毫秒,而10个线程的情况下居然要3秒多才能运行完。也就是说这个方法的耗时是不是一个常数值,他会随着线程数线性增长!

Package xmlPackage = jaxbUtil.convertXmlStrToJavaBean(messageContent, path, Package.class);

解决思路

找到原因了,那么问题就解决了一半,先看一下这个方法的内部实现

    public static <T> T convertXmlStrToJavaBean(String xmlStr, String xmlExpress, Class<T> clazz)
            throws XPathExpressionException,ParserConfigurationException, SAXException,IOException,JAXBException {
        DocumentBuilder builder = DocumentBuilderFactory.newInstance().newDocumentBuilder();
        Document document = builder.parse(new ByteArrayInputStream(xmlStr.getBytes()));
        XPath xpath = XPathFactory.newInstance().newXPath();
        Node widgetNode = (Node) xpath.evaluate(xmlExpress, document, XPathConstants.NODE);

        JAXBContext context = JAXBContext.newInstance(clazz);
        Binder<Node> binder = context.createBinder();
        return (T)binder.unmarshal(widgetNode);
    }

分析一下这个方法,每次调用的时候DocumentBuilder 、XPath 、JAXBContext 、Binder。4个东西都是需要重新创建的,而我的clazz对象是固定的Package.class所以应该也能抽取出来。所以我的第一版改进就是把这4个对象定义成了类的私有成员变量,方法改为非静态了,然后新建了一个jaxbUtil类的bean,把他注入了spring中。
其实, JAXBContext context = JAXBContext.newInstance(clazz); 只有这句语句运行时间会增长,其他语句的初始化时间基本可以忽略。具体为什么实例化的时间会随着线程数的增加而增加,我也没弄明白。


多线程

再次测试,速度已经起飞了10个线程500条数据2秒不到就处理完了。愉快的提交了测试~
过了一会测试再次反馈,速度是达标了,但是出现了无法解析的错误,需要赶紧处理。我拉下数据一看,各种问题有空指针,非法参数,考虑到我刚刚的修改,只了初始化了一个对象却有多个线程需要用,会不会线程不安全呢。于是我调了一个异常

org.xml.sax.SAXException: FWK005 parse may not be called while parsing.
        at com.sun.org.apache.xerces.internal.parsers.DOMParser.parse(DOMParser.java:263)
        at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.parse(DocumentBuilderImpl.java:28)
        at javax.xml.parsers.DocumentBuilder.parse(DocumentBuilder.java:208)

从程序逻辑来看,如果当前DocumentBuilder对象正在转换文档,此时再次请求转换文档,那么直接抛出XNIException(“FWK005 parse may not be called while parsing.”);异常。
这个问题也比较好解决,一种是对转换xml文档的方法,增加synchronized关键字,这样子不会有两个线程同时访问方法。
还有一种方法是创建一个DocumentBuilder类型的ThreadLocal变量,这样子每个线程都拥有自己的
DocumentBuilder对象,能够同时转换多个xml文件。代码如下:

private static ThreadLocal docBuildeIns = new ThreadLocal() {
    protected DocumentBuilder initialValue() {
        try {
            return DocumentBuilderFactory.newInstance().newDocumentBuilder();
        } catch (ParserConfigurationException e) {
            String msg = "DocumentBuilder 对象初始化失败!";
            log.error(msg, e);
            throw new IllegalStateException(msg, e);
        }
    } 
};

ok了同步是肯定不能用了,定义ThreadLocal变量吧,跟着这个思路,改了4个ThreadLocal变量,问题得到完美的解决!


内存溢出

一小时之后测试又过来找我了,这次手上提了把刀…… 测试反应在前20分钟,程序运行的很好,但是随着时间的推移,运行的越来越慢,直到最后几乎就不运行了。
我尝试在本地进行复现,在分析log日志的时候我发现了java.lang.OutOfMemoryError:Java heap space。啊堆溢出了,我们知道JVM中的堆存放了大量的对象,应该是有某个对象使用了但是没有进行释放。

怀疑1:

观察到使用了字节流但是没有关闭,经过查找资料发现这个流是内存读写流,在不使用时Java的垃圾回收机制会将它回收,不需要手动关闭。经过试验,也确实不是他的事。

ByteArrayInputStream byteArrayInputStream = new ByteArrayInputStream(xmlStr.getBytes());

怀疑2:
有某个变量不使用没释放,或者被static化了却没有清空。
借助MemoryAnalyzer工具进行内存的分析。在这里可以看出com.sun.xml.internal.bind.v2.runtime.AssociationMap这个Map占用了大量的内存,找到对应的类,发现在实例化Binder的时候会创建AssociationMap缓存xml节点,而Binder已经被我做成单例的bean了,随着处理的xml越来越多AssociationMap当然越来越大= =


图片.png
解决思路

既然Binder无法重复使用,那么每次都实例化一下,实例化的时间成本大约在2ms左右,时间也不会变动,不影响效率。

    Binder<Node> binder = JAXBContextThreadLocal.get().createBinder();

这里篇文章主要还是记录一下多线程中ThreadLocal的用法,在多线程的时候需要多考虑一下调用的方法是否是线程安全的。

感谢以下文章作者
Java并发编程:深入剖析ThreadLocal
ThreadLocal-面试必问深度解析

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 213,864评论 6 494
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 91,175评论 3 387
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 159,401评论 0 349
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,170评论 1 286
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,276评论 6 385
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,364评论 1 292
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,401评论 3 412
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,179评论 0 269
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,604评论 1 306
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,902评论 2 328
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,070评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,751评论 4 337
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,380评论 3 319
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,077评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,312评论 1 267
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,924评论 2 365
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,957评论 2 351

推荐阅读更多精彩内容

  • Android 自定义View的各种姿势1 Activity的显示之ViewRootImpl详解 Activity...
    passiontim阅读 171,919评论 25 707
  • Spring Web MVC Spring Web MVC 是包含在 Spring 框架中的 Web 框架,建立于...
    Hsinwong阅读 22,369评论 1 92
  • 【小小陪伴】20170718学习力践行记录D64:1、早上英语磨耳朵鹅妈妈10首,已经听了很久了 2、重复复习...
    睿依show阅读 116评论 0 0
  • 过了几天,小男孩又来找高尔基了。他在大门口大声的喊到:高尔基先生让门卫给我开门吧,我是来给您拍照的。高尔基从窗外望...
    Olivia金金阅读 423评论 1 3