Mailing-List: contact dev-help@chemistry.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@chemistry.apache.org
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8;
 format=flowed
Content-Transfer-Encoding: 8bit
Date: Thu, 22 Dec 2016 22:09:32 +0100
From: =?UTF-8?Q?Florian_M=C3=BCller?= <fmui@apache.org>
To: "Lu, Wentao" <Wentao.Lu@bchydro.com>
Cc: dev@chemistry.apache.org
Subject: Re: Slow when call cmis bridge using pure http call after a few days
In-Reply-To: <095375566B6DA042AF27048A5083FFA6394E7FD7@KDCBCHMBX1.bchydro.adroot.bchydro.bc.ca>
References: <095375566B6DA042AF27048A5083FFA6394E7C0D@KDCBCHMBX1.bchydro.adroot.bchydro.bc.ca>
 <f9bc92a3877d6d0f6d20399f22d16913@apache.org>
 <095375566B6DA042AF27048A5083FFA6394E7F1C@KDCBCHMBX1.bchydro.adroot.bchydro.bc.ca>
 <412e2f88-1935-16c6-0042-2c3839191bb7@apache.org>
 <095375566B6DA042AF27048A5083FFA6394E7FD7@KDCBCHMBX1.bchydro.adroot.bchydro.bc.ca>
Message-ID: <e4db93b953dc1f9e83358e2e6fa8ff59@apache.org>
User-Agent: RoundCube Webmail
archived-at: Thu, 22 Dec 2016 21:09:49 -0000

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-07AA990EDBBD?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-07AA990EDBBD?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-07AA990EDBBD?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=&includeAllo
>>> 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