Welcome to pay attention to the public account “JAVA Front” to view more wonderful sharing articles, mainly including source code analysis, practical application, architecture thinking, workplace sharing, product thinking and so on, at the same time, welcome to add my wechat “JAVA_front” to communicate and learn together
1 A formula
In our previous article, we used a formula to analyze why the DUBBO thread pool was full. At the beginning of this article, we should review this formula: a company with 7,200 employees clocks in from 8 a.m. to 8:30 a.m. every day, and each time the system clocks in, it takes 5 seconds. What are RT, QPS and concurrency?
RT stands for response time, and the question already tells us:
RT = 5
QPS represents the query volume per second, assuming that the check-in behavior is evenly distributed:
QPS = 7200 / (30 * 60) = 4
Concurrency represents the number of simultaneous requests processed by the system:
Concurrency = QPS x RT = 4 x 5 = 20
According to the above examples, the following formula is derived:
Concurrency = QPS x RT
If the system allocates one processing thread per request, the concurrency can be approximately equal to the number of threads. Based on the above formula, it is not difficult to see that concurrency is affected by QPS and RT, and an increase in either of these two indicators will lead to an increase in concurrency.
However, this is an ideal situation, because the amount of concurrency is limited by system capacity and cannot continue to increase. For example, the DUBBO thread pool has a limit on the number of threads. Exceeding the maximum number of threads will result in a rejection policy, which will indicate that the thread pool is full.
2 A piece of code
MyCache is a cache tool that reads data from many files into memory when initialized, and retrives data directly from memory when fetched.
public class MyCache {
private static Map<String, String> cacheMap = new HashMap<String, String>();
static {
initCacheFromFile();
}
private static void initCacheFromFile(a) {
try {
long start = System.currentTimeMillis();
System.out.println("init start");
// It takes time to simulate reading files
Thread.sleep(10000L);
cacheMap.put("K1"."V1");
System.out.println("init end cost " + (System.currentTimeMillis() - start));
} catch (Exception ex) {
}
}
public static String getValueFromCache(String key) {
returncacheMap.get(key); }}Copy the code
2.1 producers
(1) Service statement
public interface HelloService {
public String getValueFromCache(String key);
}
@Service("helloService")
public class HelloServiceImpl implements HelloService {
@Override
public String getValueFromCache(String key) {
returnMyCache.getValueFromCache(key); }}Copy the code
(2) Configuration file
<beans>
<dubbo:application name="java-front-provider" />
<dubbo:registry address=Zookeeper: / / "127.0.0.1:2181" />
<dubbo:protocol name="dubbo" port="9999" />
<dubbo:service interface="com.java.front.dubbo.demo.provider.HelloService" ref="helloService" />
</beans>
Copy the code
(3) Service release
public class Provider {
public static void main(String[] args) throws Exception {
String path = "classpath*:META-INF/spring/dubbo-provider.xml";
ClassPathXmlApplicationContext context = newClassPathXmlApplicationContext(path); System.out.println(context); context.start(); System.in.read(); }}Copy the code
2.2 consumers
(1) Configuration file
<beans>
<dubbo:application name="java-front-consumer" />
<dubbo:registry address=Zookeeper: / / "127.0.0.1:2181" />
<dubbo:reference id="helloService" interface="com.java.front.dubbo.demo.provider.HelloService" timeout="10000" />
</beans>
Copy the code
(2) Service consumption
public class Consumer {
public static void main(String[] args) throws Exception {
ClassPathXmlApplicationContext context = new ClassPathXmlApplicationContext(new String[] { "classpath*:META-INF/spring/dubbo-consumer.xml" });
context.start();
System.out.println(context);
// Simulate a large number of requests
for (int i = 0; i < 1000; i++) {
new Thread(new Runnable() {
@Override
public void run(a) {
HelloService helloService = (HelloService) context.getBean("helloService");
String result = helloService.getValueFromCache("K1"); System.out.println(result); } }).start(); }}}Copy the code
2.3 Running Results
The thread pool is full.
NettyServerWorker-5-1 WARN support.AbortPolicyWithReport: [DUBBO] Thread pool is EXHAUSTED! Thread Name: dubboServerHandler-1.1.1.1:9999, Pool Size: 200 (active: 200, core: 200, Max: 200, largest: 200), Task: 201 (completed: 1), Executor status (isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://1.1.1.1:9999! , dubbo version: 2.7.0-snapshot, current host: 1.1.1.1Copy the code
3 A Tool
According to the formula and code fragment introduced in chapter 1, it is not difficult to speculate that the thread pool is full due to the rise of RT. However, if the detailed reason needs to be analyzed, the analysis should not stop there, but also need to combine with the thread snapshot. Thread snapshot is also useful if the online server suddenly reported a thread pool full error, we can not immediately locate the problem code, this requires thread snapshot analysis.
3.1 jstack
The first way to obtain a thread snapshot is to run the jstack command to print a thread snapshot based on the JAVA process number. The command is used in three steps: determine the JAVA process number, print a thread snapshot, and analyze a thread snapshot.
(1) Determine the JAVA process number
jps -l
Copy the code(2) Print the thread snapshot
Suppose the first step yields a JAVA process number of 5678
jstack 5678 > dump.log
Copy the code(3) Analyze thread snapshots
Now we need to analyze the snapshot file dump.log. We can either open the snapshot file directly or use a tool to analyze it. I usually use a free thread snapshot analysis tool developed by IBM:
IBM Thread and Monitor Dump Analyzer for Java
Copy the code(a) How to download it
https://public.dhe.ibm.com/software/websphere/appserv/support/tools/jca/jca469.jar
Copy the code(b) How does it work
java -jar jca469.jar
Copy the code(c) How to analyze it
Use this tool to open the dump.log file and select the toolbar pie icon to analyze the thread status:
We find a large number of threads blocking at HelloServiceImpl line 48, find the corresponding code location:
public class HelloServiceImpl implements HelloService {
// omit the code......
@Override
public String getValueFromCache(String key) {
return MyCache.getValueFromCache(key); / / line 48}}Copy the codeWe assume that if MyCache getValueFromCache this method is time-consuming operation, then the thread should be blocked in this method a row, but eventually blocking HelloServiceImpl in this class, this suggests that is blocking MyCache this class initialization. Looking back at the MyCache code, it was the initialization method that took a lot of time, proving the validity of the analysis based on the thread snapshot.
public class MyCache {
private static Map<String, String> cacheMap = new HashMap<String, String>();
static {
initCacheFromFile();
}
private static void initCacheFromFile(a) {
try {
long start = System.currentTimeMillis();
System.out.println("init start");
// It takes time to simulate reading files
Thread.sleep(10000L);
cacheMap.put("K1"."V1");
System.out.println("init end cost " + (System.currentTimeMillis() - start));
} catch (Exception ex) {
}
}
}
Copy the code
3.2 DUBBO Thread Snapshot
The second way to get a thread snapshot is in the DUBBO thread pool rejection policy source code. We analyze the source code to know that DUBBO prints a thread snapshot whenever the thread pool is full.
public class AbortPolicyWithReport extends ThreadPoolExecutor.AbortPolicy {
protected static final Logger logger = LoggerFactory.getLogger(AbortPolicyWithReport.class);
private final String threadName;
private final URL url;
private static volatile long lastPrintTime = 0;
private static Semaphore guard = new Semaphore(1);
public AbortPolicyWithReport(String threadName, URL url) {
this.threadName = threadName;
this.url = url;
}
@Override
public void rejectedExecution(Runnable r, ThreadPoolExecutor e) {
String msg = String.format("Thread pool is EXHAUSTED!" +
" Thread Name: %s, Pool Size: %d (active: %d, core: %d, max: %d, largest: %d), Task: %d (completed: %d)," +
" Executor status:(isShutdown:%s, isTerminated:%s, isTerminating:%s), in %s://%s:%d!",
threadName, e.getPoolSize(), e.getActiveCount(), e.getCorePoolSize(), e.getMaximumPoolSize(), e.getLargestPoolSize(),
e.getTaskCount(), e.getCompletedTaskCount(), e.isShutdown(), e.isTerminated(), e.isTerminating(),
url.getProtocol(), url.getIp(), url.getPort());
logger.warn(msg);
// Prints a thread snapshot
dumpJStack();
throw new RejectedExecutionException(msg);
}
private void dumpJStack(a) {
long now = System.currentTimeMillis();
// Output thread snapshot every 10 minutes
if (now - lastPrintTime < 10 * 60 * 1000) {
return;
}
if(! guard.tryAcquire()) {return;
}
ExecutorService pool = Executors.newSingleThreadExecutor();
pool.execute(() -> {
String dumpPath = url.getParameter(Constants.DUMP_DIRECTORY, System.getProperty("user.home"));
System.out.println("AbortPolicyWithReport dumpJStack directory=" + dumpPath);
SimpleDateFormat sdf;
String os = System.getProperty("os.name").toLowerCase();
// Linux file location /home/xxx/dubbo_jstack.log.2021-01-01 _20:50:15
// Windows file location /user/ XXX/dubbo_jstack.log. 2020-01-01_20-50-15
if (os.contains("win")) {
sdf = new SimpleDateFormat("yyyy-MM-dd_HH-mm-ss");
} else {
sdf = new SimpleDateFormat("yyyy-MM-dd_HH:mm:ss");
}
String dateStr = sdf.format(new Date());
try (FileOutputStream jStackStream = new FileOutputStream(new File(dumpPath, "Dubbo_JStack.log" + "." + dateStr))) {
JVMUtil.jstack(jStackStream);
} catch (Throwable t) {
logger.error("dump jStack error", t);
} finally{ guard.release(); } lastPrintTime = System.currentTimeMillis(); }); pool.shutdown(); }}Copy the codeAs you can see from the thread snapshot file below, all 200 DUBBO threads are also executing at Line 48 of HelloServiceImpl, thus also locating the problem code location. However, DUBBO prints thread snapshots not in the JStack standard format, so it cannot be analyzed using IBM tools.
DubboServerHandler - 1.1.1.1:9999 - thread - Id = 230 200 RUNNABLE ats com.java.front.dubbo.demo.provider.HelloServiceImpl.getValueFromCache(HelloServiceImpl.java:48) at org.apache.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java) at org.apache.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:56) at org.apache.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:85) at org.apache.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:56)Copy the code
4 Some thoughts
The MyCache tool’s modification methods are not complicated either. You can hand them over to Spring, initialize them with the PostConstruct annotation, and declare the fetch cache method as an object method.
In fact, we found that the MyCache class syntax is correct, and initialization in a static code block is not impossible. However, due to the heavy caller traffic, MyCache was called without completing the initialization, resulting in a large number of threads blocking on the initialization method and eventually causing the thread pool to fill up. So when the flow gradually increased, quantitative change caused qualitative change, the original problem is not a problem is also exposed, which needs to attract our attention, I hope this article is helpful to you.
Welcome to pay attention to the public account “JAVA Front” to view more wonderful sharing articles, mainly including source code analysis, practical application, architecture thinking, workplace sharing, product thinking and so on, at the same time, welcome to add my wechat “JAVA_front” to communicate and learn together