apm-agent-java: Incorrect transaction duration

Describe the bug I was testing with snapshot from 9bf9d9740114dd04a8a9e5aac8ae0e6adb2d1d29 Looks like agent is calculating incorrect duration for some transactions

To Reproduce Not sure how to reproduce the issue. Seems to happen every now and then.

Debug logs

Click to expand 
2018-08-25 03:20:18.105 [http-listener-1(1)] DEBUG co.elastic.apm.impl.ElasticApmTracer - startTransaction 'GET' c08f3ce25d97217fe340c357a568805d {
2018-08-25 03:20:18.107 [http-listener-1(1)] DEBUG co.elastic.apm.impl.ElasticApmTracer - startSpan '' c08f3ce25d97217fe340c357a568805d:2 {
2018-08-25 03:20:18.107 [apm-reporter] DEBUG co.elastic.apm.report.ApmServerHttpPayloadSender - Sending payload with 2 elements to APM server http://dockdock.lan.vilant.com:8200
2018-08-25 03:20:18.108 [http-listener-1(1)] DEBUG co.elastic.apm.impl.ElasticApmTracer - } endSpan 'SELECT' c08f3ce25d97217fe340c357a568805d:2
2018-08-25 03:20:18.109 [http-listener-1(1)] DEBUG co.elastic.apm.impl.ElasticApmTracer - startSpan '' c08f3ce25d97217fe340c357a568805d:3 {
2018-08-25 03:20:18.110 [http-listener-1(1)] DEBUG co.elastic.apm.impl.ElasticApmTracer - } endSpan 'SELECT' c08f3ce25d97217fe340c357a568805d:3
2018-08-25 03:20:18.119 [apm-reporter] DEBUG co.elastic.apm.report.ApmServerHttpPayloadSender - APM server responded with status code 202
2018-08-25 03:20:18.120 [http-listener-1(1)] DEBUG co.elastic.apm.impl.ElasticApmTracer - } endTransaction '' 00000000000000000000000000000000
2018-08-25 03:20:18.793 [http-listener-1(2)] DEBUG co.elastic.apm.impl.ElasticApmTracer - startTransaction '' 685e263705ba6b0e33c40b59362c91e3 {

Document in elasticsearch:

{
  "_index": "apm-6.4.0-transaction-2018.08.25",
  "_type": "doc",
  "_id": "fARzbmUBhWJxzedF-oAw",
  "_score": 1,
  "_source": {
    "@timestamp": "2018-08-25T00:20:18.105Z",
    "processor": {
      "name": "transaction",
      "event": "transaction"
    },
    "transaction": {
      "id": "c08f3ce2-5d97-217f-e340-c357a568805d",
      "name": "GET",
      "duration": {
        "us": 3309497958390079000
      },
      "type": "request",
      "result": "HTTP 2xx",
      "sampled": true
    },
    "context": {
      "system": {
        "ip": "10.6.1.12",
        "hostname": "Linux",
        "architecture": "amd64",
        "platform": "[redacted]"
      },
      "request": {
        "http_version": "1.1",
        "method": "GET",
        "headers": {
          "accept": [
            "*/*",
            "application/json"
          ],
          "x-forwarded-proto": [
            "https",
            "https"
          ],
          "x-forwarded-for": [
            "2001:1bc8:101:ee00::5",
            "[redacted].119.14"
          ],
          "content-type": "application/json;charset=utf-8",
          "authorization": "[redacted]",
          "host": [
            "[redacted].turckvilant.cloud",
            "[redacted].turckvilant.cloud"
          ],
          "user-agent": "curl/7.52.1"
        },
        "url": {
          "full": "http://[redacted].turckvilant.cloud/[redacted]/healthcheck2http://[redacted].turckvilant.cloud/[redacted]/orders/heartbeat",
          "hostname": "[redacted].turckvilant.cloud",
          "port": "8080",
          "pathname": "/[redacted]/orders/heartbeat",
          "protocol": "http"
        },
        "socket": {
          "encrypted": false,
          "remote_address": "2001:1bc8:101:ee00::5"
        }
      },
      "response": {
        "headers": {
          "Set-Cookie": "[REDACTED]",
          "Cache-Control": "no-cache",
          "Content-Type": "application/json;charset=ISO-8859-1",
          "Date": "Sat, 25 Aug 2018 00:20:17 GMT",
          "Content-Length": "166",
          "X-Powered-By": "Servlet/3.1 JSP/2.3 (GlassFish Server Open Source Edition  4.0  Java/Oracle Corporation/1.7)"
        },
        "finished": true,
        "headers_sent": true,
        "status_code": 200
      },
      "service": {
        "agent": {
          "name": "java",
          "version": "0.7.0-SNAPSHOT"
        },
        "version": "3.1.0",
        "environment": "production",
        "language": {
          "name": "Java",
          "version": "1.7.0_141"
        },
        "runtime": {
          "name": "Java",
          "version": "1.7.0_141"
        },
        "name": "[redacted]-[redacted]"
      },
      "process": {
        "title": "/usr/lib/jvm/jdk1.7.0_141/jre/bin/java",
        "pid": 25647
      }
    },
    "beat": {
      "name": "f5f84ecd1b1e",
      "hostname": "f5f84ecd1b1e",
      "version": "6.4.0"
    },
    "host": {
      "name": "f5f84ecd1b1e"
    }
  },
  "fields": {
    "view errors": [
      "[redacted]-[redacted]"
    ],
    "error id icon": [
      null
    ],
    "@timestamp": [
      "2018-08-25T00:20:18.105Z"
    ]
  }
}

And another instance:

2018-08-26 15:26:17.102 [http-listener-1(2)] DEBUG co.elastic.apm.impl.ElasticApmTracer - startTransaction 'GET' 9bea2115f026e2af41c48c3bc9856d43 {
2018-08-26 15:26:17.107 [apm-reporter] DEBUG co.elastic.apm.report.ApmServerHttpPayloadSender - Sending payload with 1 elements to APM server http://dockdock.lan.vilant.com:8200
2018-08-26 15:26:17.109 [http-listener-1(2)] DEBUG co.elastic.apm.impl.ElasticApmTracer - startSpan '' 9bea2115f026e2af41c48c3bc9856d43:4 {
2018-08-26 15:26:17.110 [http-listener-1(2)] DEBUG co.elastic.apm.impl.ElasticApmTracer - } endSpan 'SELECT' 9bea2115f026e2af41c48c3bc9856d43:4
2018-08-26 15:26:17.112 [http-listener-1(2)] DEBUG co.elastic.apm.impl.ElasticApmTracer - } endTransaction '' 00000000000000000000000000000000

{
  "_index": "apm-6.4.0-transaction-2018.08.26",
  "_type": "doc",
  "_id": "UcQydmUBhWJxzedF_mmF",
  "_score": 1,
  "_source": {
    "@timestamp": "2018-08-26T12:26:17.102Z",
    "processor": {
      "name": "transaction",
      "event": "transaction"
    },
    "transaction": {
      "result": "HTTP 2xx",
      "sampled": true,
      "id": "9bea2115-f026-e2af-41c4-8c3bc9856d43",
      "name": "GET",
      "duration": {
        "us": 3439456955610855000
      },
      "type": "request"
    },
    "context": {
      "request": {
        "http_version": "1.1",
        "method": "GET",
        "headers": {
          "x-forwarded-for": [
            "[redacted].41.97",
            "2001:1bc8:101:ee00::5"
          ],
          "user-agent": "curl/7.52.1",
          "content-type": "application/json;charset=utf-8",
          "accept": [
            "application/json",
            "*/*"
          ],
          "authorization": "[REDACTED]",
          "host": [
            "[redacted].turckvilant.cloud",
            "[redacted].turckvilant.cloud"
          ],
          "x-forwarded-proto": [
            "https",
            "https"
          ]
        },
        "url": {
          "full": "http://[redacted].turckvilant.cloud/[redacted]/orders/heartbeathttp://[redacted].turckvilant.cloud/[redacted]/healthcheck2",
          "hostname": "[redacted].turckvilant.cloud",
          "port": "8080",
          "pathname": "/[redacted]/healthcheck2",
          "protocol": "http"
        },
        "socket": {
          "encrypted": false,
          "remote_address": "[redacted].41.97"
        }
      },
      "response": {
        "status_code": 200,
        "headers": {
          "X-Powered-By": "Servlet/3.1 JSP/2.3 (GlassFish Server Open Source Edition  4.0  Java/Oracle Corporation/1.7)",
          "Content-Type": "application/json",
          "Date": "Sun, 26 Aug 2018 12:26:16 GMT",
          "Content-Length": "34"
        },
        "finished": true,
        "headers_sent": true
      },
      "service": {
        "agent": {
          "name": "java",
          "version": "0.7.0-SNAPSHOT"
        },
        "version": "3.1.0",
        "environment": "production",
        "language": {
          "name": "Java",
          "version": "1.7.0_141"
        },
        "runtime": {
          "name": "Java",
          "version": "1.7.0_141"
        },
        "name": "[redacted]-[redacted]"
      },
      "process": {
        "pid": 25647,
        "title": "/usr/lib/jvm/jdk1.7.0_141/jre/bin/java"
      },
      "system": {
        "architecture": "amd64",
        "platform": "[redacted]",
        "ip": "10.6.1.12",
        "hostname": "Linux"
      }
    },
    "beat": {
      "name": "f5f84ecd1b1e",
      "hostname": "f5f84ecd1b1e",
      "version": "6.4.0"
    },
    "host": {
      "name": "f5f84ecd1b1e"
    }
  },
  "fields": {
    "view errors": [
      "[redacted]-[redacted]"
    ],
    "error id icon": [
      null
    ],
    "@timestamp": [
      "2018-08-26T12:26:17.102Z"
    ]
  }
}

About this issue

  • Original URL
  • State: closed
  • Created 6 years ago
  • Comments: 44 (20 by maintainers)

Commits related to this issue

Most upvoted comments

About 3 days running and no more ‘already started’ errors or ‘data validation errors’ Kibana APM graphs look OK and otherwise everything feels good now.

+1
Aketzu on Sep 17, 2018

Due to logging.log_file mishap it ended up in elasticsearch. Easy to find that “recycling 346386948” happens about 2000 times per day but very hard to say whether any of those are consecutive. Let’s see tomorrow whether we get any errors to elastic-apm.log.

+1
Aketzu on Sep 12, 2018

Installed new version. For reference, rest of error occurances with previous version:

2018-09-04 02:50:33.409
2018-09-04 20:54:58.436
2018-09-05 17:40:07.276
2018-09-06 16:40:18.100
2018-09-08 14:25:50.981
2018-09-08 21:52:17.831
2018-09-09 17:20:18.920
2018-09-09 21:14:17.198
2018-09-10 06:10:03.989
2018-09-10 10:48:28.115

So we should see in a few days whether this helps

+1
Aketzu on Sep 10, 2018
Read more comments on GitHub
← apm-agent-java: Getting this error when trying to implement apm java agent 1.32.1 for WebClient. Issue#1306 PR#2229
apm-agent-java: JIT Compilation error with Oracle JDK 7u80 →