Hi Wento, It could be a network issue of some kind. Is there a pattern? Is it slow when the bridge hasn't been accessed for a while?
There seems to be also an issue with WebLogic's HttpURLConnection. See: https://stackoverflow.com/questions/36148606/poor-performance-with-weblogics-httpurlconnection-implementation?rq=1 And: https://stackoverflow.com/questions/36080108/slow-2-way-ssl-handshake-with-weblogic-net-http-httpsurlconnection Which OpenCMIS version are you using? You could try switching the HTTP client implementation on the bridge. Maybe that helps. - Florian > Hi Florian, > > Here is the debug trace, it looks like the slowness occurs before > "Initializing AtomPub SPI", could that be SSL shake or something else? > > CMIS bridge server access log, 9:19:35 - 9:19:47 (12.609 seconds), > 2016-12-23 09:19:47 12.609 GET > /cmisbridge/atom/myrepository/content/?ID=idd_6ADB4E75-9FBB-4802-9A18-A7D80220D8B5 > 200 > > Debug log > //no debug logs before this initializing atompub spi > 2016-12-23 09:19:45,413 DEBUG [[ACTIVE] ExecuteThread: '19' for queue: > 'weblogic.kernel.Default (self-tuning)'] > [oD4sshOkz84__MiAx3i8UXjkp9Gh72i54art8gJeRVy9dENHqP5r!1954451694!1482513585060] > org.apache.chemistry.opencmis.client.bindings.spi.atompub.CmisAtomPubSpi > : Initializing AtomPub SPI... > ..................................................... > 2016-12-23 09:19:47,034 INFO [[ACTIVE] ExecuteThread: '19' for queue: > 'weblogic.kernel.Default (self-tuning)'] > [oD4sshOkz84__MiAx3i8UXjkp9Gh72i54art8gJeRVy9dENHqP5r!1954451694!1482513585060] > com.bch.filenet.cmis.bridge.MyCmisService: getContentStream ends. > > > Thanks > Wentao > > -----Original Message----- > From: Florian Müller [mailto:f...@apache.org] > Sent: 2016, December 22 1:10 PM > To: Lu, Wentao > Cc: dev@chemistry.apache.org > Subject: Re: Slow when call cmis bridge using pure http call after a few days > > Hi Wentao, > > we are running a bridge based product for several years now and have not seen > anything like this. > I'll add more logging and debug code to the bridge. That should give us a > better insight. > > > - Florian > > > >> Hi Florian, >> >> I did more testing and I think the slowness is inside the cmis bridge >> server and kind of randomly, the second call below take 15.306 end to >> end (17:55:06 - 17:55:21), but only 5 seconds in FileNet CMIS >> (17:55:16 - 17:55:21), I am wondering if there are any "lock and/or >> waiting" in the cmis bridge. >> >> CMIS bridge access log: >> 2016-12-21 17:54:09 3.008 GET >> /cmisbridge/atom/myrepository/content/?ID=idd_8016FF58-35FF-4147-81A4-07AA990EDBBD >> 200 >> 2016-12-21 17:55:21 15.306 GET >> /cmisbridge/atom/myrepository/content/?ID=idd_8016FF58-35FF-4147-81A4-07AA990EDBBD >> 200 >> 2016-12-21 17:55:23 1.141 GET >> /cmisbridge/atom/myrepository/content/?ID=idd_8016FF58-35FF-4147-81A4-07AA990EDBBD >> 200 >> >> FN CMIS access log (I enabled "time-taken" log on FileNet CMIS server): >> 2016-12-21 17:54:06 0.017 GET >> /fncmis/resources/Service?repositoryId=myrepository 200 >> 2016-12-21 17:54:07 0.105 GET >> /fncmis/resources/myrepository/Content/idd_8016FF58-35FF-4147-81A4-07A >> A990EDBBD?filter=&includeAllowableActions=&includeACL= >> 200 >> 2016-12-21 17:54:09 2.725 GET >> /fncmis/resources/myrepository/ContentStream/idd_8016FF58-35FF-4147-81A4-07AA990EDBBD/0/Report+E901.pdf >> 200 >> 2016-12-21 17:55:16 0.021 GET >> /fncmis/resources/Service?repositoryId=myrepository 200 >> 2016-12-21 17:55:16 0.104 GET >> /fncmis/resources/myrepository/Content/idd_8016FF58-35FF-4147-81A4-07A >> A990EDBBD?filter=&includeAllowableActions=&includeACL= >> 200 >> 2016-12-21 17:55:21 4.693 GET >> /fncmis/resources/myrepository/ContentStream/idd_8016FF58-35FF-4147-81A4-07AA990EDBBD/0/Report+E901.pdf >> 200 >> 2016-12-21 17:55:22 0.017 GET >> /fncmis/resources/Service?repositoryId=myrepository 200 >> 2016-12-21 17:55:22 0.089 GET >> /fncmis/resources/myrepository/Content/idd_8016FF58-35FF-4147-81A4-07A >> A990EDBBD?filter=&includeAllowableActions=&includeACL= >> 200 >> 2016-12-21 17:55:23 0.946 GET >> /fncmis/resources/myrepository/ContentStream/idd_8016FF58-35FF-4147-81A4-07AA990EDBBD/0/Report+E901.pdf >> 200 >> >> Thanks >> Wentao >> >> >> -----Original Message----- >> From: Florian Müller [mailto:f...@apache.org] >> Sent: 2016, December 21 12:14 PM >> To: Lu, Wentao; dev@chemistry.apache.org >> Subject: Re: Slow when call cmis bridge using pure http call after a >> few days >> >> >> Hi Wentao, >> >> Because your clients don't manage cookies, the LRU Cache >> implementation is a better fit >> (org.apache.chemistry.opencmis.bridge.lrucache.LruCacheBridgeServiceFactory). >> With the HttpSessionBridgeServiceFactory and without cookies you are >> accumulating a lot of useless session objects on the bridge. Please >> check if you see the same symptoms with the LRU cache. >> >> If you download documents frequently, please remove this line: >> httpConnGetContent.disconnect(); >> Without it sockets to the bridge can be reused and SSL handshakes can >> be avoided. >> >> Also make sure that you always read the full content, even if an error >> occurs somewhere. Otherwise the socket can get stuck. >> >> >> - Florian >> >>> Hi Florian, >>> >>> Thanks for your help again. >>> >>> At the moment, I am not 100% sure if the slowness is occurred on >>> FileNet CMIS server or on the CMIS bridge server, as if I restart the >>> bridge server, it back to 3 seconds. >>> >>> Does it stay slow or do you only see spikes? Wentao: It stay slow >>> until I restart bridge server. >>> >>> Are you using HTTP sessions and cookies for the cache? If so, does >>> the client always send the correct (current) cookies? >>> >>> Wentao: we extended the "HttpSessionCmisService" from the bridge >>> library, we did not set cookie in client code, snip of the client >>> code as below: >>> >>> String cmisGetContentPrefix = >>> "https://myserver/cmisbridge/atom/myrepository/content/?ID=";; >>> URL urlGetContent = new URL(cmisGetContentPrefix+idd); >>> HttpURLConnection httpConnGetContent = >>> (HttpURLConnection)urlGetContent.openConnection(); >>> httpConnGetContent.setRequestProperty("Authorization","Basic >>> "+ authStr); >>> InputStream inputStream = httpConnGetContent.getInputStream(); >>> response.setHeader("Content-Type", >>> httpConnGetContent.getContentType()); >>> response.setHeader("Content-Disposition", >>> httpConnGetContent.getHeaderField("Content-Disposition")); >>> int bytesRead = -1; >>> byte [] buffer = new byte[64000]; >>> while ((bytesRead = inputStream.read(buffer)) != -1){ >>> response.getOutputStream().write(buffer,0,bytesRead); >>> } >>> inputStream.close(); >>> httpConnGetContent.disconnect(); >>> >>> Thanks >>> Wentao >>> >>> -----Original Message----- >>> From: Florian Müller [mailto:f...@apache.org] >>> Sent: 2016, December 21 9:00 AM >>> To: dev@chemistry.apache.org >>> Cc: Lu, Wentao >>> Subject: Re: Slow when call cmis bridge using pure http call after a >>> few days >>> >>> Hi Wentao, >>> >>> The log excerpt shows that the getRepositoryInfo call takes most of >>> the time. Why it takes that long should be answered by a FileNet >>> expert (Jay?). >>> >>> The log excerpt also shows that you are creating a new OpenCMIS >>> session to your FileNet server on the bridge. If you can cache the >>> OpenCMIS session object on the bridge, you avoid the >>> getRepositoryInfo call and save a lot of time. >>> Probably you already do that but your cache evicts the session object >>> at some point. The next request has to set up a new session that then >>> calls getRepositoryInfo again, which takes time. That would explain >>> why it suddenly gets slower. >>> >>> Does it stay slow or do you only see spikes? >>> Are you using HTTP sessions and cookies for the cache? If so, does >>> the client always send the correct (current) cookies? >>> >>> >>> Btw. Use the Browser Binding, if you can. It's faster. >>> >>> >>> - Florian >>> >>> >>> >>>> Hi, >>>> >>>> We have a custom code which can't use OpenCMIS Client library, we >>>> asked them to use pure http call by assembly the getContentStream >>>> url with http basic header. The access is via cmis bridge (version >>>> 0.10) to backend FileNet CMIS. >>>> >>>> The call was fast (less than 3 second) at the beginning, but after a >>>> few days, it become slow, the response time was 20 seconds until we >>>> restart cmis bridge instance, access log as below >>>> >>>> CMIS bridge accesslog >>>> 2016-12-14 16:32:02 20.551 GET >>>> /cmisbridge/atom/myrepository/content/?ID=idd_8413BC70-2875-4517-A709-84D0D7AF9803 >>>> 200 >>>> >>>> FileNet CMIS log >>>> 127.0.0.1 - myview [14/Dec/2016:16:31:51 -0800] "GET >>>> /fncmis/resources/Service?repositoryId=myrepository HTTP/1.1" 200 >>>> 20978 >>>> 127.0.0.1 - myview [14/Dec/2016:16:32:01 -0800] "GET >>>> /fncmis/resources/ myrepository >>>> /Content/idd_8413BC70-2875-4517-A709-84D0D7AF9803?filter=&includeAll >>>> o >>>> wableActions=&includeACL=H >>>> TTP/1.1" 200 30753 >>>> 127.0.0.1 - myview [14/Dec/2016:16:32:01 -0800] "GET >>>> /fncmis/resources/myrepository/ContentStream/idd_8413BC70-2875-4517- >>>> A >>>> 709-84D0D7AF9803/0/Report+E707.pdf >>>> HTTP/1.1" 200 993683 >>>> >>>> I am wondering if there were any resources not been released >>>> properly when we use http call directly, any ideas where the >>>> slowness may come from? The other client apps using opencmis java or >>>> .net library do not have this issue. >>>> >>>> Thanks >>>> Wentao >>>> ________________________________ >>>> This email and its attachments are intended solely for the personal >>>> use of the individual or entity named above. Any use of this >>>> communication by an unintended recipient is strictly prohibited. If >>>> you have received this email in error, any publication, use, >>>> reproduction, disclosure or dissemination of its contents is >>>> strictly prohibited. Please immediately delete this message and its >>>> attachments from your computer and servers. We would also appreciate >>>> if you would contact us by a collect call or return email to notify >>>> us of this error. Thank you for your cooperation. >>>> -BCHydroDisclaimerID5.2.8.1541
