background

The early design of the system is not reasonable, and the system is often ridiculed by users for being slow. Moreover, the traffic volume of the system is expected to surge during the Double Eleven and Double Twelve, so the pressure measurement and optimization of the system is imperative

The main selection of the home interface to analyze

Application configuration

2-core 4G, logical CPU40

Application boot 2 gigabytes of memory

New generation old age default 1:2

The new generation GC collector is parNew, and the old generation GC collector is CMS

Before optimization

Pressure test data

The number of threads The average time Total number of calls Abnormal number Average throughput
120 1022 19822 8 107.2 / S

Why is throughput so low?

Jvisual shows that the CPU usage of the system is only around 3%, but it takes 1-2 seconds for memory to peak and trigger GC

Why is GC so frequent? The initial guess is that there should be a large object occupied,GC never collect

Jmap-histo PID takes up hundreds of megabytes of memory when the program is running. Why is it so large?

Jstack: A thread is WAITING in the print log.

Through code analysis, we print too much log, our log print mode is ASYNC asynchronous.

Because logs are printed asynchronously, large objects cannot be reclaimed and logs are written to disk, which leads to frequent GC and extremely low throughput

"http-nio-8000-exec-193" #2041 daemon prio=5 os_prio=0 tid=0x00007fe91c031000 nid=0x120f waiting on condition [0x00007fe9304cc000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000ab7334a8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
	at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
	at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)
	at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
	at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
	at ch.qos.logback.classic.Logger.debug(Logger.java:482)
Copy the code

I also found some repetitive logic in the code and some unnecessarily large objects

So start optimizing

To optimize the

  1. Adjusting a Log Level
  2. Cut out unnecessary logic
  3. Optimize unnecessary large objects
  4. Pipeline is used when reading redis
The number of threads The average time Total number of calls Abnormal number Average throughput
300 688 109832 0 413.2 / S