Why http request can take 15 sec with "GCM HTTP Connection Server "

Question

Implementing gcm third party server, we decided to use http integration and followed google instructions.

They provide an implementation of the integration here.

We used it and sent notifications to 500 000 users using java tasks to be more effective (we need to notify our users as quick as possible). We were surprised because http request to GCM servers could take sometimes more than 15 sec. We set log in gcm-server source and find out this issue.

Code with custom log:

public MulticastResult sendNoRetry(Message message, List<String> registrationIds) throws IOException {
    if (nonNull(registrationIds).isEmpty()) {
        throw new IllegalArgumentException("registrationIds cannot be empty");
    }
    Date startDate = new Date();
    Map<Object, Object> jsonRequest = new HashMap<Object, Object>();
    setJsonField(jsonRequest, PARAM_TIME_TO_LIVE, message.getTimeToLive());
    setJsonField(jsonRequest, PARAM_COLLAPSE_KEY, message.getCollapseKey());
    setJsonField(jsonRequest, PARAM_RESTRICTED_PACKAGE_NAME, message.getRestrictedPackageName());
    setJsonField(jsonRequest, PARAM_DELAY_WHILE_IDLE, message.isDelayWhileIdle());
    setJsonField(jsonRequest, PARAM_DRY_RUN, message.isDryRun());
    jsonRequest.put(JSON_REGISTRATION_IDS, registrationIds);
    Map<String, String> payload = message.getData();
    if (!payload.isEmpty()) {
        jsonRequest.put(JSON_PAYLOAD, payload);
    }
    String requestBody = JSONValue.toJSONString(jsonRequest);
    log.debug("JSON request: " + requestBody);
    HttpURLConnection conn;
    int status;
    Date beforeHttpRequest = new Date();
    try {
        conn = post(GCM_SEND_ENDPOINT, "application/json", requestBody);
        status = conn.getResponseCode();
    } catch (IOException e) {
        log.error("IOException posting to GCM", e);
        return null;
    }
    Date afterHttpRequest = new Date();
    String responseBody;
    if (status != 200) {
        try {
            responseBody = getAndClose(conn.getErrorStream());
            log.debug("JSON error response: " + responseBody);
        } catch (IOException e) {
            // ignore the exception since it will thrown an
            // InvalidRequestException
            // anyways
            responseBody = "N/A";
            log.error("Exception reading response: ", e);
        }
        throw new InvalidRequestException(status, responseBody);
    }

    try {
        responseBody = getAndClose(conn.getInputStream());
    } catch (IOException e) {
        log.error("IOException reading response", e);
        return null;
    }
    log.debug("JSON response: " + responseBody);
    JSONParser parser = new JSONParser();
    JSONObject jsonResponse;
    try {
        jsonResponse = (JSONObject) parser.parse(responseBody);
        int success = getNumber(jsonResponse, JSON_SUCCESS).intValue();
        int failure = getNumber(jsonResponse, JSON_FAILURE).intValue();
        int canonicalIds = getNumber(jsonResponse, JSON_CANONICAL_IDS).intValue();
        long multicastId = getNumber(jsonResponse, JSON_MULTICAST_ID).longValue();
        MulticastResult.Builder builder = new MulticastResult.Builder(success, failure, canonicalIds, multicastId);
        @SuppressWarnings("unchecked")
        List<Map<String, Object>> results = (List<Map<String, Object>>) jsonResponse.get(JSON_RESULTS);
        if (results != null) {
            for (Map<String, Object> jsonResult : results) {
                String messageId = (String) jsonResult.get(JSON_MESSAGE_ID);
                String canonicalRegId = (String) jsonResult.get(TOKEN_CANONICAL_REG_ID);
                String error = (String) jsonResult.get(JSON_ERROR);
                Result result = new Result.Builder().messageId(messageId).canonicalRegistrationId(canonicalRegId).errorCode(error)
                        .build();
                builder.addResult(result);
            }
        }
        MulticastResult multicastResult = builder.build();
        log.info("Http Request takes : "
                + (afterHttpRequest.getTime() - beforeHttpRequest.getTime()) / 1000 + " sec");
        return multicastResult;
    } catch (ParseException e) {
        throw newIoException(responseBody, e);
    } catch (CustomParserException e) {
        throw newIoException(responseBody, e);
    }
}

and the log:

2014-11-12 13:01:54,660 INFO executor-37 Sender:466  - Http Request takes : 4 sec
2014-11-12 13:01:57,383 INFO executor-49 Sender:466  - Http Request takes : 6 sec
2014-11-12 13:01:57,702 INFO executor-31 Sender:466  - Http Request takes : 6 sec
2014-11-12 13:01:58,565 INFO executor-42 Sender:466  - Http Request takes : 9 sec
2014-11-12 13:01:58,602 INFO executor-39 Sender:466  - Http Request takes : 7 sec
2014-11-12 13:01:59,477 INFO executor-45 Sender:466  - Http Request takes : 10 sec
2014-11-12 13:02:00,876 INFO executor-36 Sender:466  - Http Request takes : 20 sec
2014-11-12 13:02:01,018 INFO executor-43 Sender:466  - Http Request takes : 3 sec
2014-11-12 13:02:01,055 INFO executor-40 Sender:466  - Http Request takes : 6 sec
2014-11-12 13:02:02,440 INFO executor-41 Sender:466  - Http Request takes : 11 sec
2014-11-12 13:02:02,846 INFO executor-50 Sender:466  - Http Request takes : 5 sec
2014-11-12 13:02:03,135 INFO executor-47 Sender:466  - Http Request takes : 4 sec
2014-11-12 13:02:03,237 INFO executor-46 Sender:466  - Http Request takes : 4 sec

We tried it from different servers, and it is not a connectivity issue. ¿Someone may know why it takes so much time for a simple http request?

Answer 1

Everything ok in this code... it was as simple network issue.

I believed my server had 10 Mbytes/s upload rate, and it may be true, but in fact, it is physically far from google servers so upload rate was the bottleneck.