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:[email protected]]
Sent: 2016, December 22 1:10 PM
To: Lu, Wentao
Cc: [email protected]
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:[email protected]]
> Sent: 2016, December 21 12:14 PM
> To: Lu, Wentao; [email protected]
> 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:[email protected]]
>> Sent: 2016, December 21 9:00 AM
>> To: [email protected]
>> 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
