Bug 63482 - Application hang because of autoSizeColumn
Summary: Application hang because of autoSizeColumn
Status: RESOLVED WORKSFORME
Alias: None
Product: POI
Classification: Unclassified
Component: XSSF (show other bugs)
Version: 4.0.0-FINAL
Hardware: PC All
: P2 critical with 5 votes (vote)
Target Milestone: ---
Assignee: POI Developers List
URL:
Keywords:
Depends on: 58896
Blocks:
  Show dependency tree
 
Reported: 2019-06-03 15:32 UTC by Vladimir
Modified: 2020-03-08 14:07 UTC (History)
4 users (show)



Attachments
Snapshot of VisualVM CPU-profiling (184.90 KB, image/png)
2019-12-10 14:07 UTC, None35
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Vladimir 2019-06-03 15:32:25 UTC
I have a problem with autoSizeColumn with small number of columns and data.
I have an application which generates XLSX files in different threads. 
I have changed the POI version from 3.17 to 4.1.0 and the application became to hang on the autoSizeColumn(sheet, true) line. 
When I had removed this line or had changed to sheet.setColumnWidth(i, SMALL_COLUMN_WIDTH) the problem was resolved.

There aren't excpetions in the log file!


-----Versions-----

1) OS: Windows 10

2) Java
java version "11.0.3" 2019-04-16 LTS
Java(TM) SE Runtime Environment 18.9 (build 11.0.3+12-LTS)
Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.3+12-LTS, mixed mode)

3)
POI version: 4.1.0
Comment 1 Vladimir 2019-06-03 15:59:31 UTC
Small clarification: autoSizeColumn() works fine wit POI version 3.17 and Java 8
Comment 2 Dominik Stadler 2019-06-20 08:15:25 UTC
Can you provide a small sample application which reproduces the problem? Without it is very hard to investigate such a bug-report.
Comment 3 Cody Lerum 2019-10-04 22:30:08 UTC
I ran into this same issue today when making the move from Java 8 to Java 11 and from POI 3.17 to 4.1.0 and I've narrowed this down to a slowdown with Java 11. It doesn't matter if you are running 3.17 or 4.1.0

When running the simple reproducer (taken from the SSPerformanceTest) below with POI 4.1.0


Elapsed 2.71 seconds for arguments [HSSF, 5000, 15, 1] on Java 1.8.0_212

Elapsed 35.08 seconds for arguments [HSSF, 5000, 15, 1] on Java 11.0.4

Elapsed 33.27 seconds for arguments [HSSF, 5000, 15, 1] on Java 12.0.1

The situation seems resolved in Java 13

Elapsed 3.44 seconds for arguments [HSSF, 5000, 15, 1] on Java 13


FYI this This is still an issue on the latest nightly pulled from AdoptOpenJDK:

Elapsed 37.13 seconds for arguments [HSSF, 5000, 15, 1] on Java 11.0.5

Commenting out the sheet.autoSizeColumn(i) yields:
Elapsed 0.54 seconds for arguments [HSSF, 5000, 15, 1] on Java 11.0.5



https://gist.github.com/codylerum/5e302c4cd69e133206ddde9e50f44daa
Comment 4 None35 2019-12-10 14:07:27 UTC
Created attachment 36913 [details]
Snapshot of VisualVM CPU-profiling
Comment 5 None35 2019-12-10 14:12:17 UTC
I confirmed the problem.
It occured with POI-3.17 and POI-4.1.1 when it is used with Java 11.
With Java 8, there is no problem.

I've provided a snapshot of VisualVM CPU-profiling with POI-4.1.1 with both JVM.
It's with a small sheet.

Sorry but I can't provide the application.
Comment 6 contdespam 2020-02-10 16:19:44 UTC
I can confirm the problem on Win10 + Java 11 + POI 4.1.1.

I created a small sample project which shows that on Java 8, an export of 2000 rows with 30 columns using SXSSF takes around 19 seconds while on Java 11 it takes 2 minutes and 19 seconds.

As far as I can see, the difference comes from method 'org.apache.poi.ss.util.SheetUtil.getCellWidth(int, int, CellStyle, double, AttributedString)', the call to 'new TextLayout(str.getIterator(), fontRenderContext)' takes around 150,000 nanoseconds on Java 8 but around 1,180,000 nanoseconds on Java 11, almost 8 times as long.

Such an order of performance loss is critical on production environments where much more rows are exported.

Is there anything expected on next release?

The small sample project should be available at https://github.com/azmau/poi-perf
Comment 7 PJ Fanning 2020-02-10 17:52:36 UTC
No rewrite of SheetUtil is currently planned. TextLayout is a JavaRuntime class, not a POI class. Rewriting POI not to use TextLayout is a big undertaking.

Does your profile say what the hotspot is inside `new TextLayout` - there is a lot of code called by that constructor?

Have you tried other JREs - newer versions or later JRE/JDK implementations?
Comment 8 contdespam 2020-02-28 16:37:27 UTC
Sorry for the late response, digging some more it seems to be a known Java problem as stated in https://mail.openjdk.java.net/pipermail/2d-dev/2018-September/009454.html and the associated links and it involves a new font layout engine (harfbuzz) introduced in Java 9. For Java 9 you could still switch to the previous engine (icu) but it was removed in Java 10, so no luck for my case with Java 11.
So fingers crossed to be fixed for Java 11 and if anyone knows more about this on other JDK implementations, please let us know. I personally tried Oracle JDK, Adopt and Corretto.
Comment 9 Dominik Stadler 2020-02-28 21:38:52 UTC
As the last comment on https://bugs.openjdk.java.net/browse/JDK-8202131 states, this should be improved again in recent Java 11 and newer

A quick local test shows the following numbers of the reproducer from that issue. As far as I see all of them run fairly quickly, only Java 12 seems to run slower by a factor of 2, but this is not an LTS version of Java anyway.


Please verify if you still see a performance problem with a more recent version of Java.

$ . setJava8.sh
java version "1.8.0_201"
Java(TM) SE Runtime Environment (build 1.8.0_201-b09)
Java HotSpot(TM) 64-Bit Server VM (build 25.201-b09, mixed mode)
$ java -cp . Main
1318 Milli-seconds
1068 Milli-seconds
930 Milli-seconds

$ . setJavaOpen8.sh
openjdk version "1.8.0_242"
OpenJDK Runtime Environment (build 1.8.0_242-8u242-b08-0ubuntu3~18.04-b08)
OpenJDK 64-Bit Server VM (build 25.242-b08, mixed mode)
$ java -cp . Main
1381 Milli-seconds
995 Milli-seconds

$ . setJava11.sh
openjdk version "11.0.6" 2020-01-14
OpenJDK Runtime Environment (build 11.0.6+10-post-Ubuntu-1ubuntu118.04.1)
OpenJDK 64-Bit Server VM (build 11.0.6+10-post-Ubuntu-1ubuntu118.04.1, mixed mode, sharing)
$ java -cp . Main
906 Milli-seconds
645 Milli-seconds
306 Milli-seconds

$ . setJava12.sh
openjdk version "12-ea" 2019-03-19
OpenJDK Runtime Environment (build 12-ea+30)
OpenJDK 64-Bit Server VM (build 12-ea+30, mixed mode, sharing)
$ java -cp . Main
2404 Milli-seconds
2042 Milli-seconds

$ . setJava13.sh
openjdk version "13-ea" 2019-09-17
OpenJDK Runtime Environment (build 13-ea+31)
OpenJDK 64-Bit Server VM (build 13-ea+31, mixed mode, sharing)
$ java -cp . Main
893 Milli-seconds
547 Milli-seconds

$ . setJava14.sh
openjdk version "14-ea" 2020-03-17
OpenJDK Runtime Environment (build 14-ea+32-1423)
OpenJDK 64-Bit Server VM (build 14-ea+32-1423, mixed mode, sharing)
$ java -cp . Main
867 Milli-seconds
317 Milli-seconds

$ . setJava15.sh
openjdk version "15-ea" 2020-09-15
OpenJDK Runtime Environment (build 15-ea+6-123)
OpenJDK 64-Bit Server VM (build 15-ea+6-123, mixed mode, sharing)
$ java -cp . Main
867 Milli-seconds
308 Milli-seconds
277 Milli-seconds



When using your sample project, I see the following numbers, all of them run in under 10 seconds now:

/opt/svn/bin/setJava8.sh
java version "1.8.0_201"
Java(TM) SE Runtime Environment (build 1.8.0_201-b09)
Java HotSpot(TM) 64-Bit Server VM (build 25.201-b09, mixed mode)
Feb 28, 2020 10:35:20 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFORMATION: Excel export duration: 0m: 9s:221ms:973425ns

/opt/svn/bin/setJavaOpen8.sh
openjdk version "1.8.0_242"
OpenJDK Runtime Environment (build 1.8.0_242-8u242-b08-0ubuntu3~18.04-b08)
OpenJDK 64-Bit Server VM (build 25.242-b08, mixed mode)
Feb 28, 2020 10:35:50 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFORMATION: Excel export duration: 0m: 9s:581ms:434155ns

/opt/svn/bin/setJava11.sh
openjdk version "11.0.6" 2020-01-14
OpenJDK Runtime Environment (build 11.0.6+10-post-Ubuntu-1ubuntu118.04.1)
OpenJDK 64-Bit Server VM (build 11.0.6+10-post-Ubuntu-1ubuntu118.04.1, mixed mode, sharing)
Feb. 28, 2020 10:34:37 NACHM. ro.azmau.poiperf.POIPerformance exportToExcel
INFORMATION: Excel export duration: 0m: 3s:226ms:085367ns

/opt/svn/bin/setJava12.sh
openjdk version "12-ea" 2019-03-19
OpenJDK Runtime Environment (build 12-ea+30)
OpenJDK 64-Bit Server VM (build 12-ea+30, mixed mode, sharing)
Feb. 28, 2020 10:34:46 NACHM. ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 0m: 7s:412ms:816613ns

/opt/svn/bin/setJava13.sh
openjdk version "13-ea" 2019-09-17
OpenJDK Runtime Environment (build 13-ea+31)
OpenJDK 64-Bit Server VM (build 13-ea+31, mixed mode, sharing)
Feb. 28, 2020 10:34:51 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 0m: 3s:268ms:218231ns

/opt/svn/bin/setJava14.sh
openjdk version "14-ea" 2020-03-17
OpenJDK Runtime Environment (build 14-ea+32-1423)
OpenJDK 64-Bit Server VM (build 14-ea+32-1423, mixed mode, sharing)
Feb. 28, 2020 10:34:55 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 0m: 3s:229ms:071870ns

/opt/svn/bin/setJava15.sh
openjdk version "15-ea" 2020-09-15
OpenJDK Runtime Environment (build 15-ea+6-123)
OpenJDK 64-Bit Server VM (build 15-ea+6-123, mixed mode, sharing)
Feb. 28, 2020 10:35:00 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 0m: 3s:723ms:820141ns
Comment 10 contdespam 2020-03-02 15:18:41 UTC
Hi Dominik, thanks a lot for the effort put in your answer. However, it seems to me that your measurements regard only Linux, while my problem and Vladimir's original post concerns exporting on Windows. Am I missing something from your info?
Comment 11 Dominik Stadler 2020-03-02 16:52:48 UTC
Oh, didn't see that, then we should do some more testing/verification on that platform first.
Comment 12 Dominik Stadler 2020-03-08 13:55:57 UTC
I re-ran the tests with the latest versions of the JDK on Windows:

Sample-Application from the JDK-Bug:

/devtools/openjdk1.8.0_242_x64/bin/java
openjdk version "1.8.0_242"
OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_242-b08)
OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.242-b08, mixed mode)
1273 Milli-seconds

/devtools/jdk1.8.0_202_x64/bin/java
java version "1.8.0_202"
Java(TM) SE Runtime Environment (build 1.8.0_202-b08)
Java HotSpot(TM) 64-Bit Server VM (build 25.202-b08, mixed mode)
1268 Milli-seconds

/devtools/openjdk1.11.0_3_x64/bin/java
openjdk version "11.0.3" 2019-04-16
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.3+7)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.3+7, mixed mode)
16654 Milli-seconds

/devtools/openjdk1.12.0_1_x64/bin/java
openjdk version "12" 2019-03-19
OpenJDK Runtime Environment (build 12+33)
OpenJDK 64-Bit Server VM (build 12+33, mixed mode, sharing)
16476 Milli-seconds

/devtools/openjdk-13.0.1_x64/bin/java
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment (build 13.0.1+9)
OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
578 Milli-seconds

/devtools/openjdk-14_x64/bin/java
openjdk version "14" 2020-03-17
OpenJDK Runtime Environment (build 14+36-1461)
OpenJDK 64-Bit Server VM (build 14+36-1461, mixed mode, sharing)
549 Milli-seconds

/devtools/openjdk-15-ea+13_x64/bin/java
openjdk version "15-ea" 2020-09-15
OpenJDK Runtime Environment (build 15-ea+13-487)
OpenJDK 64-Bit Server VM (build 15-ea+13-487, mixed mode, sharing)
537 Milli-seconds

So Java 11 and Java 12 are slow here, but 13 onwards seems to be quick, actually more than twice as fast as JDK 8!
Comment 13 Dominik Stadler 2020-03-08 14:07:30 UTC
Also the sample-project on github shows the same timings.

22 seconds for JDK 8, more than 2 minutes for JDK 11 and 12, 6 seconds for JDK 13 and newer.

So I think we can close this issue now, JDK 13 and 14 are GA.

/devtools/openjdk1.8.0_242_x64/bin/java
openjdk version "1.8.0_242"
OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_242-b08)
OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.242-b08, mixed mode)
Mar 08, 2020 3:02:17 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 0m:22s:281ms:987600ns

/devtools/jdk1.8.0_202_x64/bin/java
java version "1.8.0_202"
Java(TM) SE Runtime Environment (build 1.8.0_202-b08)
Java HotSpot(TM) 64-Bit Server VM (build 25.202-b08, mixed mode)
Mar 08, 2020 3:02:42 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 0m:22s:564ms:076700ns

/devtools/openjdk1.11.0_3_x64/bin/java
openjdk version "11.0.3" 2019-04-16
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.3+7)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.3+7, mixed mode)
Mar 08, 2020 2:58:57 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 2m:26s:217ms:274600ns

/devtools/openjdk1.12.0_1_x64/bin/java
openjdk version "12" 2019-03-19
OpenJDK Runtime Environment (build 12+33)
OpenJDK 64-Bit Server VM (build 12+33, mixed mode, sharing)
Mar 08, 2020 3:01:23 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 2m:17s:935ms:624100ns

/devtools/openjdk-13.0.1_x64/bin/java
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment (build 13.0.1+9)
OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
Mar 08, 2020 3:01:38 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 0m: 6s:681ms:601800ns

/devtools/openjdk-14_x64/bin/java
openjdk version "14" 2020-03-17
OpenJDK Runtime Environment (build 14+36-1461)
OpenJDK 64-Bit Server VM (build 14+36-1461, mixed mode, sharing)
Mar 08, 2020 3:01:46 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 0m: 6s:209ms:532500ns

/devtools/openjdk-15-ea+13_x64/bin/java
openjdk version "15-ea" 2020-09-15
OpenJDK Runtime Environment (build 15-ea+13-487)
OpenJDK 64-Bit Server VM (build 15-ea+13-487, mixed mode, sharing)
Mar 08, 2020 3:01:53 PM ro.azmau.poiperf.POIPerformance exportToExcel
INFO: Excel export duration: 0m: 6s:336ms:566300ns