Bug 21876 - java.lang.OutOfMemoryError: unable to create new native thread
Summary: java.lang.OutOfMemoryError: unable to create new native thread
Status: RESOLVED INVALID
Alias: None
Product: POI
Classification: Unclassified
Component: HSSF (show other bugs)
Version: 2.0-pre2
Hardware: Sun Solaris
: P3 normal (vote)
Target Milestone: ---
Assignee: POI Developers List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2003-07-25 08:04 UTC by Fran
Modified: 2005-05-20 03:47 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Fran 2003-07-25 08:04:47 UTC
Hello,

My system is weblogic 6.1 and solaris 5.8. The JDK is 1.3.1

I use HSSF to generate an excel file that sizes 550kb (so a big file)

It works 2 times, the third there is an error ‘java.lang.OutOfMemoryError: 
unable to create new native thread’

I've tried with the option -verbosegc to see the works of the garbage collector:

There is a need of lot of memory for HSSF work, but when the exception is 
raised, there is plenty of memory available. (In fact, I see that the used 
memory goes from 9M to 25M for the generation of one file, go back to 9M after 
the file generation)


So I suppose there is a memory leak (but in a ‘native call’?) and it may be 
linked to the OS/JDK

Regard from a Frenchman living in Belgium
Comment 1 Fran 2003-07-25 08:43:56 UTC
Changing the parameters -ms128m -mx128m has no effect.
Comment 2 Andy Oliver 2003-07-25 12:20:33 UTC
now that is weird.  98% chance this has nothing to do with POI per se.  Who's JDK?
Comment 3 Fran 2003-07-25 12:32:18 UTC
The JDK is java version "1.3.1_01"

I found a kind of turnaround with the option -Xss128k ==> To limit the thread 
stack size

Now I can generate more (up to 10) but the pb remains
Comment 4 Andy Oliver 2003-07-25 12:41:15 UTC
POI has some places where its recursive but it runs all in 1 thread.  My suspicion is that Weblogic 
has sprung a leak and that you're just catching this in POI because its a big long running process.  
You'd eventually see it elsewhere.  In "top" does it show you're running close to your max memory?  
It could also be that its when its expanding the heap.
Comment 5 Fran 2003-07-25 13:32:54 UTC
Sorry I don't have top installed on my system, so I will use the solaris tools

So based on http://developers.sun.com/solaris/articles/prstat.html#fpcpu

I have search for memory/threads leak:

Here is the result:

<----------------------------------------------------------->
bash-2.03$ prstat -p 12936 15 >server.out
bash-2.03$ tail -f server.out 

   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    144M   64M sleep   58    0   0:00.10 0.1% java/11
Total: 1 processes, 11 lwps, load averages: 1.16, 3.58, 2.27
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    144M   64M sleep   58    0   0:00.10 0.0% java/11
Total: 1 processes, 11 lwps, load averages: 0.90, 3.41, 2.24
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    144M   64M sleep   58    0   0:00.10 0.0% java/11
Total: 1 processes, 11 lwps, load averages: 0.70, 3.24, 2.20
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    144M   64M sleep   58    0   0:00.10 0.0% java/11
Total: 1 processes, 11 lwps, load averages: 0.55, 3.09, 2.16
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    145M   65M sleep   58    0   0:00.10 1.9% java/15
Total: 1 processes, 15 lwps, load averages: 0.47, 2.95, 2.13
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    146M   66M sleep   58    0   0:00.10 1.4% java/16
Total: 1 processes, 16 lwps, load averages: 0.45, 2.82, 2.10
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    147M   68M sleep   58    0   0:00.10 3.3% java/50
Total: 1 processes, 50 lwps, load averages: 0.39, 2.69, 2.07
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    151M   72M sleep   58    0   0:00.10 5.5% java/200
Total: 1 processes, 200 lwps, load averages: 0.41, 2.58, 2.04
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    153M   76M cpu0    38    0   0:00.00 6.5% java/291
Total: 1 processes, 291 lwps, load averages: 0.43, 2.48, 2.02
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    156M   80M sleep   58    0   0:00.10 6.7% java/410
Total: 1 processes, 410 lwps, load averages: 0.35, 2.36, 1.98
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    158M   84M sleep   58    0   0:00.10 7.3% java/516
Total: 1 processes, 516 lwps, load averages: 0.32, 2.26, 1.96
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    161M   88M sleep   58    0   0:00.10 6.9% java/625
Total: 1 processes, 625 lwps, load averages: 0.36, 2.17, 1.93
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    164M   93M cpu1    38    0   0:00.00 7.9% java/735
Total: 1 processes, 735 lwps, load averages: 0.36, 2.09, 1.91
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    167M   96M sleep   58    0   0:00.10 7.4% java/857
Total: 1 processes, 857 lwps, load averages: 0.43, 2.02, 1.89
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    171M  102M cpu2    32    0   0:00.00 8.0% java/993
Total: 1 processes, 993 lwps, load averages: 0.47, 1.95, 1.87
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    174M  106M cpu3    31    0   0:00.00 8.0% java/1110
Total: 1 processes, 1110 lwps, load averages: 0.40, 1.86, 1.84
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    176M  110M sleep   58    0   0:00.00 7.2% java/1198
Total: 1 processes, 1198 lwps, load averages: 0.44, 1.80, 1.82
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    179M  114M cpu2    38    0   0:00.00 7.8% java/1299
Total: 1 processes, 1299 lwps, load averages: 0.46, 1.74, 1.80
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    180M  116M sleep   58    0   0:00.10 6.0% java/1341
Total: 1 processes, 1341 lwps, load averages: 0.40, 1.66, 1.77
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    180M  116M sleep   58    0   0:00.10 2.8% java/1342
Total: 1 processes, 1342 lwps, load averages: 0.31, 1.58, 1.74
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    181M  117M sleep   58    0   0:00.10 2.1% java/1345
Total: 1 processes, 1345 lwps, load averages: 0.26, 1.51, 1.71
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    181M  117M cpu1    11    0   0:00.01 7.0% java/1345
Total: 1 processes, 1345 lwps, load averages: 0.30, 1.46, 1.69
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    181M  118M sleep   58    0   0:00.10 8.5% java/1345
Total: 1 processes, 1345 lwps, load averages: 0.37, 1.41, 1.68
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    181M  118M sleep   58    0   0:00.10 7.1% java/1345
Total: 1 processes, 1345 lwps, load averages: 0.38, 1.37, 1.65
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    181M  118M sleep   58    0   0:00.10 3.6% java/1346
Total: 1 processes, 1346 lwps, load averages: 0.30, 1.30, 1.62
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    181M  119M sleep   58    0   0:00.00 5.5% java/1346
Total: 1 processes, 1346 lwps, load averages: 0.34, 1.26, 1.61
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    181M  119M sleep   58    0   0:00.10 6.6% java/1346
Total: 1 processes, 1346 lwps, load averages: 0.36, 1.22, 1.59
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    181M  119M sleep   58    0   0:00.10 3.4% java/1346
Total: 1 processes, 1346 lwps, load averages: 0.27, 1.16, 1.56
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    182M  119M sleep   58    0   0:00.10 1.8% java/1346
Total: 1 processes, 1346 lwps, load averages: 0.23, 1.10, 1.54
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    182M  119M sleep   58    0   0:00.10 0.9% java/1346
Total: 1 processes, 1346 lwps, load averages: 0.26, 1.07, 1.52
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    182M  119M sleep   58    0   0:00.10 5.0% java/1350
Total: 1 processes, 1350 lwps, load averages: 0.33, 1.05, 1.50
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    182M  120M sleep   58    0   0:00.10 7.6% java/1350
Total: 1 processes, 1350 lwps, load averages: 0.35, 1.02, 1.48
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    182M  120M sleep   58    0   0:00.10 8.5% java/1350
Total: 1 processes, 1350 lwps, load averages: 0.36, 0.98, 1.46
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    182M  120M sleep   58    0   0:00.10 5.7% java/1350
Total: 1 processes, 1350 lwps, load averages: 0.31, 0.94, 1.44
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    182M  121M run     51    0   0:00.15 7.1% java/1350
Total: 1 processes, 1350 lwps, load averages: 0.39, 0.93, 1.43
<----------------------------------------------------------->

(sorry for this borring copy paste)

So it is possible that the server application is leaking threads...(NLWP)

Note: 
 - from NLWP=15 to 1345: one file generation
 - from NLWP=1345 to 1350: big seach on database

even if I don't understand why weblogic use so much threads for POI, I'm agree 
to say that my bug should be assigned to bea

Thank's for being so reactive
Comment 6 Andy Oliver 2003-07-25 13:57:37 UTC
hey it looks like it just hit the 128M, increase to 256M  BTW How much memory is on this system?  
Is it dedicated?
Comment 7 Fran 2003-07-25 14:26:18 UTC
This server is our development platform and is not dedicated to my application.
(Memory is increased when needed, actually 4G ram)

The log has been done for one file. The problem is that memory is not freed 
after. e.g. Now I have:

   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP       
 12936 dcstar    285M  247M sleep   58    0   0:00.11 0.5% java/5324

(and only 5 reports generated...)

note: the POI class is wrapped into a bean that has a 'request' scope
Comment 8 Andy Oliver 2003-07-25 14:37:14 UTC
I think you're holding on to objects that you shouldn't.  I can't say for sure without seeing your 
code, but something is leaking.  Can you attach the output from the garbage collector?  I want to 
make sure its not POI.  (It shouldn't be if you're newing another up every time)
Comment 9 Fran 2003-07-25 15:13:04 UTC
the code for the exel generation is simple
=> a collection is created, using data from different DAO class (connected to 
oracle and corba)

once the collection is ready, i do the excel ==> no special layout, just 10 
sheet, about 1000 record per sheet, 30 column

    public HSSFWorkbook doTheExcel(JspWriter out) throws IOException {
        HSSFSheet sheet;
        HSSFWorkbook wb = new HSSFWorkbook();
        int myint = 0;
        Collection allDan =  new ReportBean().getDanList();
        Dan oneDan;
        Iterator iter = allDan.iterator();
        out.flush();
        while (iter.hasNext()){
            myint++;
            oneDan = (Dan) iter.next();
            sheet = wb.createSheet("PortPassport_"+ oneDan.getDan_name()
+"_"+myint);
            out.println("<li><b>DAN </b> "+oneDan.getDan_name());
            out.flush();
            doTitle(sheet);
            doContent(sheet,oneDan.getDan_id());
            out.println("<font class=DarkGreen>  ok</font></li>");
        }
        out.print("</MENU>");
        return wb;
    }


with the -verbosegc option I have (part of the log)

<----------------------------------------------------------->
[GC 58111K->44763K(130560K), 0.0836426 secs]
[GC 58267K->44651K(130560K), 0.0813831 secs]
[GC 58155K->44658K(130560K), 0.0774749 secs]
[GC 58162K->44685K(130560K), 0.0781372 secs]
[GC 58189K->44830K(130560K), 0.0856084 secs]
[GC 58334K->45019K(130560K), 0.0884809 secs]
[GC 58521K->45088K(130560K), 0.0909737 secs]
[GC 58592K->45019K(130560K), 0.0832764 secs]
[GC 58521K->45141K(130560K), 0.0815629 secs]
[GC 58645K->45066K(130560K), 0.0825176 secs]
[GC 58568K->45186K(130560K), 0.0820842 secs]
[GC 58690K->45389K(130560K), 0.0905469 secs]
[GC 58893K->45406K(130560K), 0.0989173 secs]
[GC 58910K->46923K(130560K), 0.1802498 secs]
[GC 60427K->47006K(130560K), 0.1081365 secs]
[GC 60510K->47044K(130560K), 0.0802481 secs]
[GC 60548K->47101K(130560K), 0.0815010 secs]
[GC 60605K->47348K(130560K), 0.0879132 secs]
[GC 60852K->47362K(130560K), 0.0946540 secs]
[GC 60866K->47326K(130560K), 0.0864550 secs]
[GC 60830K->47536K(130560K), 0.0881128 secs]
[GC 61040K->47588K(130560K), 0.0939117 secs]
[GC 61092K->47468K(130560K), 0.0857027 secs]
[GC 60971K->47679K(130560K), 0.0871233 secs]
[GC 61183K->47576K(130560K), 0.0844342 secs]
[GC 61079K->47752K(130560K), 0.0895072 secs]
[GC 61256K->48867K(130560K), 0.1623272 secs]
[GC 62371K->49246K(130560K), 0.1264462 secs]
[GC 62750K->49342K(130560K), 0.1036315 secs]
[GC 62845K->49507K(130560K), 0.0903454 secs]
[GC 63011K->49474K(130560K), 0.0909878 secs]
[GC 62978K->49757K(130560K), 0.0974931 secs]
[GC 63261K->49760K(130560K), 0.0991084 secs]
[GC 63264K->49649K(130560K), 0.0891965 secs]
[GC 63153K->50081K(130560K), 0.1121554 secs]
[GC 63585K->51016K(130560K), 0.1641777 secs]
[GC 64520K->50955K(130560K), 0.1054016 secs]
<Jul 25, 2003 10:34:01 AM CEST> <Error> <HTTP> <[WebAppServletContext
(1102187,DCStarWebApp,/DCStarWebApp)] Servlet failed with Exception
java.lang.OutOfMemoryError: unable to create new native thread
	at java.lang.Thread.start(Native Method)
	at org.apache.log4j.PropertyConfigurator.configureAndWatch
(PropertyConfigurator.java:375)
	at org.apache.log4j.PropertyConfigurator.configureAndWatch
(PropertyConfigurator.java:355)
	at mobistar.dcstar.tools.ErrorBean.<init>(ErrorBean.java:46)
	at jsp_servlet._Jsp.__errorpage_include._jspService
(__errorpage_include.java:96)
	at weblogic.servlet.jsp.JspBase.service(JspBase.java:27)
	at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:265)
	at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:304)
	at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:200)
	at weblogic.servlet.internal.RequestDispatcherImpl.include
(RequestDispatcherImpl.java:482)
	at weblogic.servlet.internal.RequestDispatcherImpl.include
(RequestDispatcherImpl.java:308)
	at weblogic.servlet.jsp.PageContextImpl.include
(PageContextImpl.java:116)
	at weblogic.servlet.jsp.PageContextImpl.handlePageException
(PageContextImpl.java:269)
	at jsp_servlet._Jsp.__popup_HSSF._jspService(__popup_HSSF.java:146)
	at weblogic.servlet.jsp.JspBase.service(JspBase.java:27)
	at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:265)
	at weblogic.servlet.internal.ServletStubImpl.invokeServlet
(ServletStubImpl.java:200)
	at weblogic.servlet.internal.WebAppServletContext.invokeServlet
(WebAppServletContext.java:2546)
	at weblogic.servlet.internal.ServletRequestImpl.execute
(ServletRequestImpl.java:2260)
	at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:139)
	at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:120)
> 
<----------------------------------------------------------->

for this test i have "-ms128m -mx128m" (but "-ms256m -mx256m" has the same 
effect, there is still free memory)


an other part of the log file with "-ms64m -mx64m" to see the action of a full 
GC:

<----------------------------------------------------------->
[GC 57847K->51140K(65280K), 0.1227375 secs]
[GC 57860K->51153K(65280K), 0.1218409 secs]
[GC 57873K->51312K(65280K), 0.1386660 secs]
[GC 58032K->51879K(65280K), 0.1718578 secs]
[Full GC 58599K->21266K(65280K), 2.0990213 secs]
[GC 27986K->21304K(65280K), 0.1174647 secs]
[GC 28023K->21809K(65280K), 0.1361481 secs]
[GC 28529K->21737K(65280K), 0.1250673 secs]
[GC 28457K->22345K(65280K), 0.1266070 secs]
[GC 29065K->22432K(65280K), 0.1251829 secs]
[GC 29152K->22434K(65280K), 0.1254387 secs]
[GC 29154K->22433K(65280K), 0.1226090 secs]
[GC 29153K->22430K(65280K), 0.1269320 secs]
[GC 28748K->24307K(65280K), 0.1471761 secs]
[GC 31027K->25197K(65280K), 0.1567875 secs]
[GC 31917K->25391K(65280K), 0.2083542 secs]
[GC 32110K->25447K(65280K), 0.2917099 secs]
[Full GC 28557K->13166K(65280K), 1.4535354 secs]
<----------------------------------------------------------->

(first Full GC is automatic, second is forced)
Comment 10 Ian P. Springer 2003-10-23 21:04:35 UTC
It's possible you're hitting a max set in the kernel - ie, max threads per 
process. I believe BEA provides recommended kernel param settings somewhere on 
their website.

Ian
Comment 11 Ian P. Springer 2003-10-23 21:24:14 UTC
then again, maybe not... the following post says that there is no such thing as 
a per-process thread limit in Solaris..
http://www.sunmanagers.org/pipermail/summaries/2002-February/002355.html

maybe you could play with some of the other threading-related JVM options. i 
found this page that discusses them in detail:
http://java.sun.com/docs/hotspot/threads/threads.html
Comment 12 Avik Sengupta 2005-05-20 11:47:59 UTC
Doesnt look like a POI issue. POI does have memory issues, but this is not one
of them, I think.