2

I asked this question on the SF developer site, but didn't hear back. Hopefully, somebody here has seen this before, and can help me out.

We have boiled it down to a few cURL calls for reproducibility. Unfortunately, it is reproducible every day - but only once, after the first slow REST call, all subsequent calls are fast. The first API call to authenticate is fast, but the first to query the /services/data/v39.0/query API is slow. It appears that the instance is warming or caching somehow, but we can't find any documentation about this.

Has anybody seen anything like this before? 30s calls are just too slow for a simple select.


Steps for reproducing - First, we authenticate:

curl -v --trace-time -X POST https://test.salesforce.com/services/oauth2/token  -H 'content-type: multipart/form-data'  -F grant_type=password  -F client_id=<snip>    -F client_secret=<snip>  -F username=<snip>    -F password=<snip>

cURL verbose of that call:

10:12:09.125368 * About to connect() to test.salesforce.com port 443 (#0)
10:12:09.125867 * Trying 136.147.58.173...
10:12:09.147686 * Connected to test.salesforce.com (136.147.58.173) port 443 (#0)
10:12:09.148953 * successfully set certificate verify locations:
10:12:09.149214 * CAfile: none CApath: /etc/ssl/certs
10:12:09.149905 * SSLv3, TLS handshake, Client hello (1):
10:12:09.171806 * SSLv3, TLS handshake, Server hello (2):
10:12:09.172253 * SSLv3, TLS handshake, CERT (11):
10:12:09.174550 * SSLv3, TLS handshake, Server finished (14):
10:12:09.175193 * SSLv3, TLS handshake, Client key exchange (16):
10:12:09.175473 * SSLv3, TLS change cipher, Client hello (1):
10:12:09.176019 * SSLv3, TLS handshake, Finished (20):
10:12:09.196838 * SSLv3, TLS change cipher, Client hello (1):
10:12:09.197305 * SSLv3, TLS handshake, Finished (20):
10:12:09.197607 * SSL connection using AES256-SHA
10:12:09.197919 * Server certificate:
10:12:09.198192 * subject: C=US; ST=California; L=San Francisco; O=Salesforce.com, Inc; OU=Applications; CN=test.salesforce.com
10:12:09.198481 * start date: 2015-06-05 00:00:00 GMT
10:12:09.198741 * expire date: 2018-06-04 23:59:59 GMT
10:12:09.199137 * subjectAltName: test.salesforce.com matched
10:12:09.199435 * issuer: C=US; O=Symantec Corporation; OU=Symantec Trust Network; CN=Symantec Class 3 Secure Server CA - G4
10:12:09.199793 * SSL certificate verify ok.
10:12:09.200266 > POST /services/oauth2/token HTTP/1.1
10:12:09.200266 > User-Agent: curl/7.29.0
10:12:09.200266 > Host: test.salesforce.com
10:12:09.200266 > Accept: */*
10:12:09.200266 > Content-Length: 712
10:12:09.200266 > Expect: 100-continue
10:12:09.200266 > content-type: multipart/form-data; boundary=----------------------------5f6c77e4d919
10:12:09.200266 >
10:12:09.218608 < HTTP/1.1 100 Continue
10:12:09.592160 < HTTP/1.1 200 OK
10:12:09.592452 < Date: Wed, 03 May 2017 15:12:19 GMT
10:12:09.592745 < Strict-Transport-Security: max-age=31536000; includeSubDomains
10:12:09.593017 < X-Content-Type-Options: nosniff
10:12:09.593286 < X-XSS-Protection: 1; mode=block
10:12:09.593539 < Content-Security-Policy: reflected-xss block;report-uri /_/ContentDomainCSPNoAuth?type=xss
10:12:09.593784 < Content-Security-Policy: referrer origin-when-cross-origin
10:12:09.594033 < Set-Cookie: BrowserId=<snip>;Path=/;Domain=.salesforce.com;Expires=Sun, 02-Jul-2017 15:12:19 GMT
10:12:09.594283 < Expires: Thu, 01 Jan 1970 00:00:00 GMT
10:12:09.594630 < Pragma: no-cache
10:12:09.594894 < Cache-Control: no-cache, no-store
10:12:09.595144 < X-ReadOnlyMode: false
10:12:09.595406 < Content-Type: application/json;charset=UTF-8
10:12:09.595671 < Vary: Accept-Encoding
10:12:09.595920 < Transfer-Encoding: chunked
10:12:09.596204 <
10:12:09.596619 * Connection #0 to host test.salesforce.com left intact

Returning:

{"access_token":"<snip>","instance_url":"https://cs54.salesforce.com","id":"<snip>","token_type":"Bearer","issued_at":"<snip>","signature":"<snip>"}

From here, we attempt a simple select Id limit 1, but it takes almost 30 seconds:

curl -v --trace-time -X GET \
'https://cs54.salesforce.com/services/data/v39.0/query?q=SELECT%20Id%20FROM%20Account%20LIMIT%201' \
  -H 'authorization: Bearer <snip>

Verbose (don't worry about the time this was run - 3p vs 10a, we are concerned about the time from intialization to return):

curl -v --trace-time -X GET \
>  'https://cs54.salesforce.com/services/data/v39.0/query?q=SELECT%20Id%20FROM%Account%20LIMIT%201' \
>   -H 'authorization: Bearer <snip>
15:03:54.066383 * About to connect() to cs54.salesforce.com port 443 (#0)
15:03:54.066855 *   Trying 136.147.103.22...
15:03:54.104193 * Connected to cs54.salesforce.com (136.147.103.22) port 443 (#0)
15:03:54.105318 * successfully set certificate verify locations:
15:03:54.105583 *   CAfile: none CApath: /etc/ssl/certs
15:03:54.106125 * SSLv3, TLS handshake, Client hello (1):
15:03:54.142363 * SSLv3, TLS handshake, Server hello (2):
15:03:54.142774 * SSLv3, TLS handshake, CERT (11):
15:03:54.144940 * SSLv3, TLS handshake, Server finished (14):
15:03:54.145588 * SSLv3, TLS handshake, Client key exchange (16):
15:03:54.145858 * SSLv3, TLS change cipher, Client hello (1):
15:03:54.146462 * SSLv3, TLS handshake, Finished (20):
15:03:54.185332 * SSLv3, TLS change cipher, Client hello (1):
15:03:54.185789 * SSLv3, TLS handshake, Finished (20):
15:03:54.186074 * SSL connection using AES256-SHA
15:03:54.186335 * Server certificate:
15:03:54.186606 *        subject: C=US; ST=California; L=San Francisco; O=Salesforce.com, Inc; OU=Applications; CN=*.salesforce.com
15:03:54.186889 *        start date: 2015-02-14 00:00:00 GMT
15:03:54.187141 *        expire date: 2018-02-14 23:59:59 GMT
15:03:54.187421 *        subjectAltName: cs54.salesforce.com matched
15:03:54.187692 *        issuer: C=US; O=Symantec Corporation; OU=Symantec Trust Network; CN=Symantec Class 3 Secure Server CA - G4
15:03:54.188013 *        SSL certificate verify ok.
15:03:54.188432 > GET /services/data/v39.0/query?q=SELECT%20Id%20FROM%Account%20LIMIT%201 HTTP/1.1
15:03:54.188432 > User-Agent: curl/7.29.0
15:03:54.188432 > Host: cs54.salesforce.com
15:03:54.188432 > Accept: */*
15:03:54.188432 > authorization: Bearer <snip>
15:03:54.188432 >
15:04:11.267080 < HTTP/1.1 200 OK
15:04:11.267389 < Date: Wed, 03 May 2017 20:04:04 GMT
15:04:11.267633 < X-Content-Type-Options: nosniff
15:04:11.267900 < X-XSS-Protection: 1; mode=block
15:04:11.268178 < Content-Security-Policy: reflected-xss block;report-uri /_/ContentDomainCSPNoAuth?type=xss
15:04:11.268423 < Content-Security-Policy: referrer origin-when-cross-origin
15:04:11.268659 < Set-Cookie: BrowserId=<snip>;Path=/;Domain=.salesforce.com;Expires=Sun, 02-Jul-2017 20:04:04 GMT
15:04:11.268894 < Expires: Thu, 01 Jan 1970 00:00:00 GMT
15:04:11.269139 < Sforce-Limit-Info: api-usage=34/5000000
15:04:11.269380 < Content-Type: application/json;charset=UTF-8
15:04:11.269616 < Vary: Accept-Encoding
15:04:11.269852 < Transfer-Encoding: chunked
15:04:11.270089 <
15:04:11.270493 * Connection #0 to host cs54.salesforce.com left intact

Returning:

{"totalSize":1,"done":true,"records":[{"attributes":{"type":"<snip>","url<snip>"},"Id":"<snip>"}]}
  • Did you find the solution ? – Franck Garnier Oct 9 '17 at 8:18
  • No, nobody from SalesForce was able to help, and we got nowhere even with our reproducible failures (above). In the end, we just ran a cron job every few minutes with a simple select that kept the connection "warm" so that we never had the 30s timeout issue in the first place. It isn't a pretty solution, but it works for us. – GP Fisher Oct 10 '17 at 13:11
  • In my case, I need to add an index in order to reduce the query time. – Franck Garnier Oct 11 '17 at 6:39
0

I realize this question is quite old, but since it has come to the top of the queue, I thought I'd respond to it. From the data you've provided:

//Time the query actually occurs during your call:

15:03:54.188432 > GET /services/data/v39.0/query?q=SELECT%20Id%20FROM%Account%20LIMIT%201 HTTP/1.1

//Time when "success" returned from your REST call

15:04:11.267080 < HTTP/1.1 200 OK

Elapsed Query Time: 15:04:11 - 15:03:54 = 17 seconds

The remainder of your time appears to be related to authentication

You don't say how large the database is that you're querying this from. Essentially, you're asking for a random, non-specific, AccountId (an indexed field) from an unknown number of Accounts. Some would refer to this as a "non-selective" query.

Its true your query is not in the cache the first time you call it in your integration which also applies to the randomization algorithm used internally for selecting the actual account. I'd speculate that's likely the cause of the issue that you're having, particularly if the database has more than 50,000 Accounts. The larger the database you're querying, the longer this type of query would be expected to take the first time you make it since it is "non-specific" in nature and Salesforce will need to break up the database into smaller tables before it can select and return a random account.

0

Ideally querying (pk) index field should not this much of time. To idenfity the where slowness is you do following things.

On high level slowness can be at 3 level

A. Client side - as you are using curl, there is very low chance this can be valid reason.
B. Network - its possible. check how is your network speed when you are running these test
C. Server - Most probability issue is here

To zero down the issue, try following steps

  1. Run same query in developer console and see the response time- if its taking same time there as well then you will need to work with support to re-create index of id field.

  2. See if there is performance degradation due any of processing that is going on in background(async apex/ apis) on your org.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.