[Bug] Too many threads will cause blocked

[szqZZZ]

Search before asking

• I had searched in the issues and found no similar issues.

Apache SkyWalking Component

Java Agent (apache/skywalking-java)

What happened

Version
Skywalking：8.7.0
SpringBoot + tomcat +druid +Mysql 5.7

A function create 10000 threads.and the thread job just execute a simple SQL.
When my application started with Skywalking and used in druid, Thread was blocked.

In my guess, i think some of SW-agent thread blocked those "pool-5-thread-XXX".

java code:

 private static volatile ListeningExecutorService executor = MoreExecutors.listeningDecorator(new ThreadPoolExecutor(
            0,
            20000,
            120L,
            TimeUnit.SECONDS,
            new SynchronousQueue<Runnable>(),
            Executors.defaultThreadFactory()));

    public void updateCount(){
        for(int i = 0; i < 10000; i++) {
            executor.execute(new Thread(() ->{
                userMapper.updateByPrimaryKey(1);
            }));
        }
    }

#### 线程状态排查
- 因为猜想可能是因为上报数据造成的影响，大概看了相关线程，底层使用grpc netty通信，线程数也不多，因为不清楚skywalking的具体实现，没有头绪
- 查看系统cpu，在提交10000个任务时robot.jar进程cpu使用率很高，开始排查线程cpu使用

top -Hp 5980 -> 5992 cpu使用率高

printf "%x" 5992 -> 1768
jstack 5980|grep -A 20 '0x1768'

"SkywalkingAgent-5-JVMService-produce-0" #8 daemon prio=5 os_prio=0 tid=0x00007f11dc5b1800 nid=0x1768 runnable [0x00007f11c4f73000]
java.lang.Thread.State: RUNNABLE at sun.management.ThreadImpl.getThreadInfo1(Native Method) at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:178)

    at org.apache.skywalking.apm.agent.core.jvm.thread.ThreadProvider.getThreadMetrics(ThreadProvider.java:40)
    at org.apache.skywalking.apm.agent.core.jvm.JVMService.run(JVMService.java:103)
    at org.apache.skywalking.apm.util.RunnableWithExceptionProtection.run(RunnableWithExceptionProtection.java:33)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

#### JVMService
- 上面线程堆栈信息指向了主要cpu的耗费是在监控中的 getThreadInfo1 jni调用（cpu高时，线程堆栈信息都是一样的， 是在 ThreadProvider.getThreadMetrics方法的获取线程信息上）
- JVMService大概就是启用了两个定时调度线程，每秒获取并上报jvm相关信息

// org.apache.skywalking.apm.agent.core.jvm.thread.ThreadProvider
ThreadInfo[] threadInfos = threadMXBean.getThreadInfo(threadMXBean.getAllThreadIds(), 0);

- 因为随着线程数越大就越卡，猜想可能是线程数据多了，获取线程信息造成的问题

## 验证猜想
虽然线程数增加后，需要上报skywalking-server的数据并没有增加，但是还是需要排查上报数据的影响，确认是只是获取监控信息造成的影响，而不是上报监控信息时影响的

#### 自定义监控

// 不启用skywalking-agent，但是自己启动一个线程信息的监控，并打印

public void startMetric() {
        if (!metricScheduleInited) {
            synchronized (JobExecutor.class) {
                if (!metricScheduleInited) {
                    metricScheduleInited = true;
                    scheduledExecutorService = Executors.newSingleThreadScheduledExecutor(
                            new DefaultNamedThreadFactory("JVMService-produce"));

                    scheduledExecutorService.scheduleAtFixedRate(new RunnableWithExceptionProtection(
                            new MetricRunnable(),
                            new RunnableWithExceptionProtection.CallbackWhenException() {
                                @Override
                                public void handle(Throwable t) {
                                    log.error("JVMService produces metrics failure.", t);
                                }
                            }
                    ), 0, 1, TimeUnit.SECONDS);
                }
            }
        }


    }

    public static class MetricRunnable implements Runnable {

        @Override
        public void run() {
            long currentTimeMillis = System.currentTimeMillis();
            try {
                long startTs = System.currentTimeMillis();
                JVMMetric.Builder jvmBuilder = JVMMetric.newBuilder();
                jvmBuilder.setTime(currentTimeMillis);
                jvmBuilder.setCpu(CPUProvider.INSTANCE.getCpuMetric());
                jvmBuilder.addAllMemory(MemoryProvider.INSTANCE.getMemoryMetricList());
                jvmBuilder.addAllMemoryPool(MemoryPoolProvider.INSTANCE.getMemoryPoolMetricsList());
                jvmBuilder.addAllGc(GCProvider.INSTANCE.getGCList());
                jvmBuilder.setThread(ThreadProvider.INSTANCE.getThreadMetrics());
                jvmBuilder.setClazz(ClassProvider.INSTANCE.getClassMetrics());
                log.info("jvm metric: {}, 耗时： {}ms", jvmBuilder, System.currentTimeMillis() - startTs);
            } catch (Exception e) {
                log.error("Collect JVM info fail.", e);
            }
        }
    }

监控结果

• 线程数低的时候，cpu没啥异常，获取监控信息的耗时也都是 0ms
• 提交10000个任务后，新增了近10000个线程，cpu飙高，jvm metric 耗时升到了1500ms左右
• 也就是说，就算没有skywalking-agent的信息上报相关，也能复现，初步定位就是这个获取大批量线程信息导致的

GetThreadInfo native方法简单分析

# services/management.cpp jmm_GetThreadInfo 方法
for (int i = 0; i < num_threads; i++) {
        jlong tid = ids_ah->long_at(i);
        JavaThread* jt = find_java_thread_from_id(tid);
        ThreadSnapshot* ts;
        
# services/management.cpp find_java_thread_from_id 方法
// Helper functions
static JavaThread* find_java_thread_from_id(jlong thread_id) {
  assert(Threads_lock->owned_by_self(), "Must hold Threads_lock");

  JavaThread* java_thread = NULL;
  // Sequential search for now.  Need to do better optimization later.
  for (JavaThread* thread = Threads::first(); thread != NULL; thread = thread->next()) {
    oop tobj = thread->threadObj();
    if (!thread->is_exiting() &&
        tobj != NULL &&
        thread_id == java_lang_Thread::thread_id(tobj)) {
      java_thread = thread;
      break;
    }
  }
  return java_thread;
}

• 可以看出，获取每个线程的信息每次都是串行遍历搜索到线程

解决办法v1

• 业务上，即使是查库的io的操作，但是不是还是可以考虑下是否需要【10000】个线程？是否有更快？数据库的压力？
• 大概只定位到说线程多的时候，因为是串行的搜索线程，10000个线程就是10000*10000次搜索，所以肯定是很耗费cpu的
  getThreadInfo调用后面涉及的是系统调用了，大概定位到的上面的信息，可以先排查一下，如果去除线程状态的监控或者将监控的频次调低问题是否能解决
• apm-agent-core 包下的JVMService监控调度是写死的，如果需要调低频次，需要修改源码

解决办法v2

因为修改获取线程监控信息的方法效率低，jdk中源码中也写了需要优化的相关注释，
往后看了jdk11和jdk17中根据线程ids的获取线程信息的代码，大概是将所有线程放到一个list中，还是通过遍历所有线程然后挨个match，应该还是效率低的

想其他替代方法，想到jstack dump所有线程信息，这种其实就是一次性dump jvm中所有alive的线程信息。
我们监控这里的场景就是获取jvm的所有线程信息，没必要说先获取到id，然后通过id单个搜索

修改为dumpAllThreads方法，测试下来，10000个线程工作时，往线程池提交任务是快了很多了，不至于阻塞请求
(提交任务之前大概50+m，现在1到2秒。但是实际执行任务的耗时还是跟之前一样的，简单逻辑的单个任务还是比较慢，因为线程数太多了。。)
cpu不会飙高到100%这样了，10~50左右，之前的监控信息consumer的线程状态采样多有是TIMED_WAITING，不至于是一直RUNNABLE占用在获取线程信息这个栈上了

    threadInfos = threadMXBean.dumpAllThreads(false, false);

[wu-sheng]

This is not even a real case. 1000 threads could burn CPU load easily.
If you are just for fun, this is your own responsibility. Don't submit this strange and unreasonable case to the community.

[szqZZZ]

It's not for fun.
Actually, We do have this kind of business with high concurrency.
What I wonder is.In same case. Why is c3p0 can work ,druid can not.

Also, I admit that it is really strange to create so many threads, but for developers, if skywalking is not integrated, their code can work, but the integration can not work. So it's hard to convince them to change the existing code. What I wonder is the root cause behind this and whether there are other similar performance problems. Because of this case, a serious accident has occurred in our production environment.

[wu-sheng]

It is super common, you are at the breaking edge. One more threads and codes running from agent crash the codes.
This is a wrong case no matter what you are going to do. Java codes should not like this.

[szqZZZ]

Thanks for your answer.
I will try to convince developers to optimize their code.

[szqZZZ]

My colleague found the root cause of the problem, and I updated his solution in the content. It is proved to be effective after the test. The root cause is that there is a performance problem with the getThreadInfo function of the ThreadProvider class in the case of very many threads.We used "dumpAllThreads(false,false)" to solve the problem @wu-sheng