问题背景:

  上周发现了一个spark job的执行时间从原来的10-15分钟延迟到了7个小时!wtf,这是出了什么事引起了这么大的性能问题!!

  立马查看job的运行日志,发现多次运行都是在某一个固定的stage速度特别慢,大概在5000-6000s,这样的stage一共有3-4次。究竟是什么样的原因引起这样的问题,第一个想法是寻找之前执行时间短的任务和现在执行时间长的任务有哪些不同的地方:1,检查spark提交的参数,包括executor个数,内存配置和核数配置,发现前后都没有改动;2,检查git代码仓库master的代码变更,发现前后有3次提交。现在我把问题的最大可能性放在这些代码的改动上。

问题排查:

  查看代码改动,首先想到的就是diff两个版本的代码:发布master在git上都会留下tag,在发布系统jenkins上找到两个发布的release tag,diff之。

  从diff结果看,这几次提交主要是添加了新功能,添加新的工具类,java bean的重构(抽取公共的属性作为父类属性),和我们的job逻辑相关的代码基本没有改动,从代码逻辑上并没有看出什么大的性能问题。

  排查陷入困境。。。

  受到同事启发,决定把改动之前的tag复制出一个新的branch(我们称之为before),把改动之后的tag复制一个新的branch(称之为after),把before和after之间的差异分批次加到before上,执行before,看加那些代码时会出现问题(实在差不出了问题所在,只能选择笨方法,一点一点试)。分批次加到before上,在Intelij idea上有个简单方法,分支切换到before,右键项目->Git->Compare with branch,选择after分支,diff两者区别,这时候diff页面上两分支不同的代码旁边会有>>的箭头形状,可以快速把要添加的代码加到before分支。

  先把最可能影响我们job执行的代码加到了before分支,执行都没有问题。。。

  继续把其他的代码分批加到before分支,(这是个体力活,添加代码-run job-添加代码-run job)

  分了5-6次之后,发现加了三个java bean的重构后job变慢,???改了bean能导致job性能变差,有点怀疑人生

  检查跟job相关的bean,除了抽取了公共属性为父类之外,重写了hashcode和equals方法!!!会不会是这个引起的

    @Override
    public boolean equals(Object obj) {
        if(Objects.nonNull(obj) && obj instanceof XXX){
            return Objects.equals(hashCode(),obj.hashCode());
        }
        return false;
    }

    @Override
    public int hashCode() {
        String value = x1 +
                x2 +
                x3 +
                x4 +
                x5 +
                x6 +
                x7 +
                x8 +
                x9;
        return StringUtils.trim(value).hashCode();
    }

  代码如上,类名这里修改为XXX,字段修改为x1,x2,x3,x4,x5,x6,x7,x8,x9

  写一个test,循环100w次 执行equals,发现也是秒秒钟跑完!!!

  继续回到性能差的那块逻辑里排查,找可能会用到model的equals方法的地方

  有重大发现,对于修改了equals方法的model,有一个removeAll操作:从一个List<XXX> source中安条件filter出一些实例,作为list1,又list2 = source.removeAll(list1);作为list2,这里的source大概在几十万到100万的数据量,list1里几乎是source的全量(此次聚合对应的分组区分度不高,所以在每一个执行器上数据量较大)

  而removeAll时会调用model的equals方法,时间复杂度为m*n(n为source的数量,m为list1的数量),在千亿-万亿的equals操作下,任何耗时的操作都会成千亿-万亿倍增加,所以会出现没有修改任何逻辑,只重写了equals方法就会出现性能问题。

  贴一下ArrayList的源码:

/**
     * Removes from this list all of its elements that are contained in the
     * specified collection.
     *
     * @param c collection containing elements to be removed from this list
     * @return {@code true} if this list changed as a result of the call
     * @throws ClassCastException if the class of an element of this list
     *         is incompatible with the specified collection
     * (<a href="Collection.html#optional-restrictions">optional</a>)
     * @throws NullPointerException if this list contains a null element and the
     *         specified collection does not permit null elements
     * (<a href="Collection.html#optional-restrictions">optional</a>),
     *         or if the specified collection is null
     * @see Collection#contains(Object)
     */
    public boolean removeAll(Collection<?> c) {
        Objects.requireNonNull(c);
        return batchRemove(c, false);
    }


private boolean batchRemove(Collection<?> c, boolean complement) {
        final Object[] elementData = this.elementData;
        int r = 0, w = 0;
        boolean modified = false;
        try {
            for (; r < size; r++)
                if (c.contains(elementData[r]) == complement)
                    elementData[w++] = elementData[r];
        } finally {
            // Preserve behavioral compatibility with AbstractCollection,
            // even if c.contains() throws.
            if (r != size) {
                System.arraycopy(elementData, r,
                                 elementData, w,
                                 size - r);
                w += size - r;
            }
            if (w != size) {
                // clear to let GC do its work
                for (int i = w; i < size; i++)
                    elementData[i] = null;
                modCount += size - w;
                size = w;
                modified = true;
            }
        }
        return modified;
    }

  可以看出,先按照source的size做循环,循环内判断contains,

      for (; r < size; r++)
                if (c.contains(elementData[r]) == complement)
                    elementData[w++] = elementData[r];

  我们再看一下ArrayList(被remove的也是ArrayList类型)的contains

/**
     * Returns <tt>true</tt> if this list contains the specified element.
     * More formally, returns <tt>true</tt> if and only if this list contains
     * at least one element <tt>e</tt> such that
     * <tt>(o==null ? e==null : o.equals(e))</tt>.
     *
     * @param o element whose presence in this list is to be tested
     * @return <tt>true</tt> if this list contains the specified element
     */
    public boolean contains(Object o) {
        return indexOf(o) >= 0;
    }

    /**
     * Returns the index of the first occurrence of the specified element
     * in this list, or -1 if this list does not contain the element.
     * More formally, returns the lowest index <tt>i</tt> such that
     * <tt>(o==null ? get(i)==null : o.equals(get(i)))</tt>,
     * or -1 if there is no such index.
     */
    public int indexOf(Object o) {
        if (o == null) {
            for (int i = 0; i < size; i++)
                if (elementData[i]==null)
                    return i;
        } else {
            for (int i = 0; i < size; i++)
                if (o.equals(elementData[i]))
                    return i;
        }
        return -1;
    }

  indexOf内部又一层循环,时间复杂度为m*n

  虽然问题是equals由 == 操作变为9个字段拼接做hashcode 这个变更引起的,但核心问题还在removeAll,before没有出现问题只是因为==操作快,大概产生2-3分钟的执行时间并没有引起问题和关注。重写equals会增加一些时间,在极大的基数上就产生了性能问题

问题解决:

  去掉removeAll,用两个filter代替(满足业务逻辑为准)

效果:

  job执行7-8分钟,比before版本还快2-3分钟,因为去掉了千亿-万亿次 equals(虽然==很快)

经过两天多的排查,终于解决掉了问题。这个事情让我重新对List 的removeAll有了新认识,也认识到一个道理,对于你认为简单的东西 才是最容易挖坑的地方

04-07 19:09