Collect memory metrics for spans and requests

[asgrim]

No description provided.

[asgrim]

@cschneid how should memory metrics be recorded in the span/request payload, should they be recorded as tags or something? What should the keys be etc.?

[asgrim]

Current proposal looks like this (i.e. a memory_usage object on the StartSpan, StopSpan, StartRequest, StopRequest payloads):

{
  "BatchCommand": {
    "commands": [
      {
        "StartRequest": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "timestamp": "2019-10-10T07:44:17.935070Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3788704,
            "peak_allocated": 4194304,
            "peak_used": 3828504
          }
        }
      },
      {
        "StartSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "be83f554-f727-4e70-8d6f-b102eee1600a",
          "parent_id": null,
          "operation": "Controller\/Yay",
          "timestamp": "2019-10-10T07:44:17.935691Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3815224,
            "peak_allocated": 4194304,
            "peak_used": 3858280
          }
        }
      },
      {
        "StartSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "4679263d-28af-4fda-a8d6-f9a50b22b7e0",
          "parent_id": "be83f554-f727-4e70-8d6f-b102eee1600a",
          "operation": "Test\/foo",
          "timestamp": "2019-10-10T07:44:17.935805Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3817456,
            "peak_allocated": 4194304,
            "peak_used": 3858280
          }
        }
      },
      {
        "StartSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "9971dca3-987e-4a7f-b29f-10d87ba113b6",
          "parent_id": "4679263d-28af-4fda-a8d6-f9a50b22b7e0",
          "operation": "Test\/bar",
          "timestamp": "2019-10-10T07:44:18.936114Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3819312,
            "peak_allocated": 4194304,
            "peak_used": 3858280
          }
        }
      },
      {
        "TagSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "9971dca3-987e-4a7f-b29f-10d87ba113b6",
          "tag": "stack",
          "value": {},
          "timestamp": "2019-10-10T07:44:19.937578Z"
        }
      },
      {
        "StopSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "9971dca3-987e-4a7f-b29f-10d87ba113b6",
          "timestamp": "2019-10-10T07:44:19.936384Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3819800,
            "peak_allocated": 4194304,
            "peak_used": 3858280
          }
        }
      },
      {
        "TagSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "4679263d-28af-4fda-a8d6-f9a50b22b7e0",
          "tag": "stack",
          "value": {},
          "timestamp": "2019-10-10T07:44:19.937936Z"
        }
      },
      {
        "StopSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "4679263d-28af-4fda-a8d6-f9a50b22b7e0",
          "timestamp": "2019-10-10T07:44:19.937668Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3843160,
            "peak_allocated": 4194304,
            "peak_used": 3883992
          }
        }
      },
      {
        "StartSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "4b5f1a2d-1d1d-4d36-8b4e-60020dffd730",
          "parent_id": "be83f554-f727-4e70-8d6f-b102eee1600a",
          "operation": "DB\/test",
          "timestamp": "2019-10-10T07:44:19.938330Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3851848,
            "peak_allocated": 4194304,
            "peak_used": 3888744
          }
        }
      },
      {
        "StopSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "4b5f1a2d-1d1d-4d36-8b4e-60020dffd730",
          "timestamp": "2019-10-10T07:44:19.938406Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3851960,
            "peak_allocated": 4194304,
            "peak_used": 3888744
          }
        }
      },
      {
        "TagSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "be83f554-f727-4e70-8d6f-b102eee1600a",
          "tag": "stack",
          "value": {},
          "timestamp": "2019-10-10T07:44:19.938700Z"
        }
      },
      {
        "StopSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "be83f554-f727-4e70-8d6f-b102eee1600a",
          "timestamp": "2019-10-10T07:44:19.938449Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3851752,
            "peak_allocated": 4194304,
            "peak_used": 3888744
          }
        }
      },
      {
        "TagRequest": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "tag": "testtag",
          "value": "1.23",
          "timestamp": "2019-10-10T07:44:19.938181Z"
        }
      },
      {
        "StartSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "56819413-758f-4e0b-9884-a00ff5c35c74",
          "parent_id": null,
          "operation": "Test\/qux",
          "timestamp": "2019-10-10T07:44:19.938833Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3856536,
            "peak_allocated": 4194304,
            "peak_used": 3888744
          }
        }
      },
      {
        "StopSpan": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "span_id": "56819413-758f-4e0b-9884-a00ff5c35c74",
          "timestamp": "2019-10-10T07:44:19.938900Z",
          "memory_usage": {
            "allocated": 4194304,
            "used": 3856648,
            "peak_allocated": 4194304,
            "peak_used": 3888744
          }
        }
      },
      {
        "FinishRequest": {
          "request_id": "34231c62-ea4c-4e14-914e-deb14b609163",
          "timestamp": null,
          "memory_usage": null
        }
      }
    ]
  }
}

[asgrim]

Aside: looks like in FinishRequest, the timestamp, and memory_usage is not populated, I suspect Request->stop() is never being called (automatically). I'll create a new ticket to investigate.

[cschneid]

We use two memory metrics in scout:

• An overall request memory change. Grab the memory as first span starts, get memory used after last span finishes. This gets reported as a request tag: memory_deltaand value of megabytes diff.
• A per-span allocation start counter, stop counter and total. Under the keys: start_allocations, stop_allocations and allocations. https://github.com/scoutapp/scout_apm_python/blob/master/src/scout_apm/core/tracked_request.py#L245-L247

[asgrim]

OK, so in #89 I've added memory_delta as a TagRequest that is added on stop() call.

Just to clarify; should this value really be in Megabytes? I've put it in as just bytes for now, but I can just divide by 1000000 to get the Mb value (presumably, as a double rather than int?).

As for per-span allocations, in PHP allocation "counts" are not recorded, the only stats about PHP we can get are:

• memory_get_usage(false) memory used by current script
• memory_get_usage(true) allocated memory by PHP (not all is necessarily used by current script, or any other script, memory is allocated in chunks by PHP's memory manager)
• memory_get_peak_usage(false) current peak usage for current script
• memory_get_peak_usage(true) as above, but for peak usage

Not sure what to suggest for spans then, apart from adding a memory_delta tag for each of them, which is do-able? Let me know what you'd prefer...

[cschneid]

Yes in megabytes. It's not the cleanest but that matches the way we report in Ruby and Python. I imagine we'll revisit at some point when there's a clear use case, but for now it's mostly used as a debugging measure in environments like heroku where huge increases can get your server killed.

[cschneid]

If we can't capture allocation counts that's fine, lets just not add any tags for that for now.

I'm unsure what the UI would need to change in order to support per-span memory usage change vs. our existing Ruby/Python supported count of allocations. The issue w/ usage is that memory that is allocated and GC'd away wouldn't get counted, or perhaps counted inconsistently.