chemistry-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Florian Müller <f...@apache.org>
Subject Re: Slow when call cmis bridge using pure http call after a few days
Date Fri, 23 Dec 2016 18:07:30 GMT
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:fmui@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:fmui@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:fmui@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



Mime
View raw message