Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Replace expensive node json calls by jq #1342

Closed
wants to merge 4 commits into from

Conversation

Dune-jr
Copy link

@Dune-jr Dune-jr commented Dec 31, 2019

Since I'm having CPU load issues on my pi0, I went to check for some expensive calls that could be optimized away. I found this call:

function find_valid_ns_glucose {
# TODO: use jq for this if possible
cat cgm/ns-glucose.json | json -c "minAgo=(new Date()-new Date(this.dateString))/60/1000; return minAgo < 10 && minAgo > -5 && this.glucose > 38"
}

node /usr/local/bin/json --help takes 14 seconds on my rasp, so I gladly replaced it with a jq call. It's quite inexpensive and I did some testing to make sure it outputs the exact same string.

The only caveat is that it assumes that the time in cgm/ns-glucose.json is formatted like

"%Y-%M-%DT%H:%M:%S.000Z"

which I believe is safe.

Here is some output (with -100 instead of -10):

  • with node json (14s user, 30s system):
CLICK ME

pi@pancreas:~/myopenaps $ cat cgm/ns-glucose.json | node /usr/local/bin/json -c "minAgo=(new Date()-new Date(this.dateString))/60/1000; return minAgo < 100 && minAgo > -5 && this.glucose > 38"
time [
  {
    "_id": "1577798746303128152c1fbb",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:25:46.000Z",
    "dateString": "2019-12-31T13:25:46.000Z",
    "rssi": 100,
    "direction": "Flat",
    "sgv": 96,
    "date": 1577798746196,
    "unfiltered": 105412,
    "filtered": 105412,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 96
  },
  {
    "_id": "157779844630559233724d87",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:20:46.000Z",
    "dateString": "2019-12-31T13:20:46.000Z",
    "rssi": 100,
    "direction": "Flat",
    "sgv": 100,
    "date": 1577798446195,
    "unfiltered": 109647,
    "filtered": 109647,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 100
  },
  {
    "_id": "1577798146394e2f22f3eb02",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:15:46.000Z",
    "dateString": "2019-12-31T13:15:46.000Z",
    "rssi": 100,
    "direction": "FortyFiveDown",
    "sgv": 105,
    "date": 1577798146293,
    "unfiltered": 113882,
    "filtered": 113882,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 105
  },
  {
    "_id": "1577797846461eb0dff039b8",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:10:46.000Z",
    "dateString": "2019-12-31T13:10:46.000Z",
    "rssi": 100,
    "direction": "FortyFiveDown",
    "sgv": 113,
    "date": 1577797846332,
    "unfiltered": 122588,
    "filtered": 122588,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 113
  },
  {
    "_id": "157779754634003dfe489491",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:05:46.000Z",
    "dateString": "2019-12-31T13:05:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 122,
    "date": 1577797546290,
    "unfiltered": 131529,
    "filtered": 131529,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 122
  },
  {
    "_id": "15777972469264b0b85f4d7b",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:00:46.000Z",
    "dateString": "2019-12-31T13:00:46.000Z",
    "rssi": 100,
    "direction": "FortyFiveDown",
    "sgv": 137,
    "date": 1577797246875,
    "unfiltered": 146000,
    "filtered": 146000,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 137
  },
  {
    "_id": "15777969464366d445275b35",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:55:46.000Z",
    "dateString": "2019-12-31T12:55:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 146,
    "date": 1577796946393,
    "unfiltered": 154824,
    "filtered": 154824,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 146
  },
  {
    "_id": "15777966464232dd46a17692",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:50:46.000Z",
    "dateString": "2019-12-31T12:50:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 158,
    "date": 1577796646386,
    "unfiltered": 166706,
    "filtered": 166706,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 158
  },
  {
    "_id": "15777963465338f23c5e0d94",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:45:46.000Z",
    "dateString": "2019-12-31T12:45:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 169,
    "date": 1577796346489,
    "unfiltered": 178118,
    "filtered": 178118,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 169
  },
  {
    "_id": "15777960466311f9ac776c6b",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:40:46.000Z",
    "dateString": "2019-12-31T12:40:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 179,
    "date": 1577796046586,
    "unfiltered": 188235,
    "filtered": 188235,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 179
  },
  {
    "_id": "157779574653386f5c1617cf",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:35:46.000Z",
    "dateString": "2019-12-31T12:35:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 194,
    "date": 1577795746486,
    "unfiltered": 202706,
    "filtered": 202706,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 194
  },
  {
    "_id": "1577795446528bf01ca9a605",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:30:46.000Z",
    "dateString": "2019-12-31T12:30:46.000Z",
    "rssi": 100,
    "direction": "DoubleDown",
    "sgv": 205,
    "date": 1577795446484,
    "unfiltered": 214353,
    "filtered": 214353,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 205
  },
  {
    "_id": "1577795146524be53887f15f",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:25:46.000Z",
    "dateString": "2019-12-31T12:25:46.000Z",
    "rssi": 100,
    "direction": "DoubleDown",
    "sgv": 224,
    "date": 1577795146486,
    "unfiltered": 233412,
    "filtered": 233412,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 224
  }
]

  • with jq (0.1s user, 0.38s system):
CLICK ME

pi@pancreas:~/myopenaps $ time jq \
>         --arg AT_LATEST   "`date -u +'%Y-%m-%dT%H:%M:%S.000Z' --date '5 minutes'`"\
>         --arg AT_EARLIEST "`date -u +'%Y-%m-%dT%H:%M:%S.000Z' --date '-100 minutes'`"\
>         '[.[] | (select (.dateString >= $AT_EARLIEST)) | (select (.dateString <= $AT_LATEST)) | (select (.glucose > 38))]' cgm/ns-glucose.json
[
  {
    "_id": "1577798746303128152c1fbb",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:25:46.000Z",
    "dateString": "2019-12-31T13:25:46.000Z",
    "rssi": 100,
    "direction": "Flat",
    "sgv": 96,
    "date": 1577798746196,
    "unfiltered": 105412,
    "filtered": 105412,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 96
  },
  {
    "_id": "157779844630559233724d87",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:20:46.000Z",
    "dateString": "2019-12-31T13:20:46.000Z",
    "rssi": 100,
    "direction": "Flat",
    "sgv": 100,
    "date": 1577798446195,
    "unfiltered": 109647,
    "filtered": 109647,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 100
  },
  {
    "_id": "1577798146394e2f22f3eb02",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:15:46.000Z",
    "dateString": "2019-12-31T13:15:46.000Z",
    "rssi": 100,
    "direction": "FortyFiveDown",
    "sgv": 105,
    "date": 1577798146293,
    "unfiltered": 113882,
    "filtered": 113882,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 105
  },
  {
    "_id": "1577797846461eb0dff039b8",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:10:46.000Z",
    "dateString": "2019-12-31T13:10:46.000Z",
    "rssi": 100,
    "direction": "FortyFiveDown",
    "sgv": 113,
    "date": 1577797846332,
    "unfiltered": 122588,
    "filtered": 122588,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 113
  },
  {
    "_id": "157779754634003dfe489491",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:05:46.000Z",
    "dateString": "2019-12-31T13:05:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 122,
    "date": 1577797546290,
    "unfiltered": 131529,
    "filtered": 131529,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 122
  },
  {
    "_id": "15777972469264b0b85f4d7b",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T13:00:46.000Z",
    "dateString": "2019-12-31T13:00:46.000Z",
    "rssi": 100,
    "direction": "FortyFiveDown",
    "sgv": 137,
    "date": 1577797246875,
    "unfiltered": 146000,
    "filtered": 146000,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 137
  },
  {
    "_id": "15777969464366d445275b35",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:55:46.000Z",
    "dateString": "2019-12-31T12:55:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 146,
    "date": 1577796946393,
    "unfiltered": 154824,
    "filtered": 154824,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 146
  },
  {
    "_id": "15777966464232dd46a17692",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:50:46.000Z",
    "dateString": "2019-12-31T12:50:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 158,
    "date": 1577796646386,
    "unfiltered": 166706,
    "filtered": 166706,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 158
  },
  {
    "_id": "15777963465338f23c5e0d94",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:45:46.000Z",
    "dateString": "2019-12-31T12:45:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 169,
    "date": 1577796346489,
    "unfiltered": 178118,
    "filtered": 178118,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 169
  },
  {
    "_id": "15777960466311f9ac776c6b",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:40:46.000Z",
    "dateString": "2019-12-31T12:40:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 179,
    "date": 1577796046586,
    "unfiltered": 188235,
    "filtered": 188235,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 179
  },
  {
    "_id": "157779574653386f5c1617cf",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:35:46.000Z",
    "dateString": "2019-12-31T12:35:46.000Z",
    "rssi": 100,
    "direction": "SingleDown",
    "sgv": 194,
    "date": 1577795746486,
    "unfiltered": 202706,
    "filtered": 202706,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 194
  },
  {
    "_id": "1577795446528bf01ca9a605",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:30:46.000Z",
    "dateString": "2019-12-31T12:30:46.000Z",
    "rssi": 100,
    "direction": "DoubleDown",
    "sgv": 205,
    "date": 1577795446484,
    "unfiltered": 214353,
    "filtered": 214353,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 205
  },
  {
    "_id": "1577795146524be53887f15f",
    "noise": 1,
    "device": "MIAOMIAO",
    "sysTime": "2019-12-31T12:25:46.000Z",
    "dateString": "2019-12-31T12:25:46.000Z",
    "rssi": 100,
    "direction": "DoubleDown",
    "sgv": 224,
    "date": 1577795146486,
    "unfiltered": 233412,
    "filtered": 233412,
    "type": "sgv",
    "utcOffset": 0,
    "glucose": 224
  }
]

real	0m0.386s
user	0m0.117s
sys	0m0.057s

Note: I wanted to use jq's strptime and strftime (https://stackoverflow.com/a/49263320/3660320) but it is not necessary since the dates are formatted in ISO 8601 (jqlang/jq#1056 (comment))

TODO: I did not test this in a real loop.

@Dune-jr
Copy link
Author

Dune-jr commented Dec 31, 2019

I now realize that since minAgo seems to be an integer (?) in return minAgo < 10 && minAgo > -5, the strictly equivalent semantics would be to use

        --arg AT_LATEST   "`date -u +'%Y-%m-%dT%H:%M:%S.000Z' --date '4 minutes'`"\
        --arg AT_EARLIEST "`date -u +'%Y-%m-%dT%H:%M:%S.000Z' --date '-9 minutes'`"\

instead. I imagine this is not very important

@Dune-jr
Copy link
Author

Dune-jr commented Dec 31, 2019

I am not familiar with monitor-xdrip.sh, but this patch could also be used here:

if cat xdrip/glucose.json | json -c "minAgo=(new Date()-new Date(this.dateString))/60/1000; return minAgo < 10 && minAgo > -5 && this.glucose > 38" | grep -q glucose; then

@Dune-jr Dune-jr changed the title Replace expensive node json call by jq in find_valid_ns_glucose Replace expensive node json calls by jq Dec 31, 2019
@Dune-jr
Copy link
Author

Dune-jr commented Dec 31, 2019

Patched the other location + another call that could be replaced identically by jq, saving a lot of time:

pi@pancreas:~/myopenaps $ time json -f upload/latest-treatments.json -a created_at eventType 
time jq -r '.[] |.created_at + " " + .eventType' upload/latest-treatments.json
2019-12-31T15:48:28+02:00 Temp Basal
2019-12-31T15:32:57+02:00 Temp Basal
2019-12-31T15:15:30+02:00 Temp Basal
2019-12-31T14:05:56+02:00 Temp Basal
2019-12-31T13:49:31+02:00 Correction Bolus

real	0m44.844s
user	0m15.323s
sys	0m0.401s
pi@pancreas:~/myopenaps $ time jq -r '.[] |.created_at + " " + .eventType' upload/latest-treatments.json
2019-12-31T15:48:28+02:00 Temp Basal
2019-12-31T15:32:57+02:00 Temp Basal
2019-12-31T15:15:30+02:00 Temp Basal
2019-12-31T14:05:56+02:00 Temp Basal
2019-12-31T13:49:31+02:00 Correction Bolus

real	0m0.161s
user	0m0.039s
sys	0m0.012s

Note that it is probably still overkill for what it does.

There is one last call in oref0-monitor-cgm.sh:

grepr "json -f"
oref0-monitor-cgm.sh:16:    && json -f monitor/glucose-raw-merge.json -a sgv raw dateString | head -n 4

but I do not use a g4 so I cannot possibly test that one.

Copy link
Contributor

@scottleibrand scottleibrand left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM. Happy to merge to dev once it's been tested on a looping rig.

@sulkaharo
Copy link
Collaborator

This will break the date handling in OpenAPS further from how it works now, by assuming a specific date format for Nightscout CGM data. Nightscout only guarantees the CGM and treatment dates comply with ISO 8601 and can be both normalised to UTC or use the local time zoned format, with or without millisecond precision. You might see this code work depending on the data sources you have for the data in Nightscout, but this will not work for all data sources. Please do not add more code that doesn't use a real date parser - I can see how making the system more performant is good, but this shouldn't make OpenAPS less compatible with external data sources.

@Dune-jr
Copy link
Author

Dune-jr commented Jan 1, 2020

The only caveat is that it assumes that the time in cgm/ns-glucose.json is formatted like

"%Y-%M-%DT%H:%M:%S.000Z"

which I believe is safe.

@sulkaharo so this assumption was wrong. It seems the parsing job falls back on OpenAPS :(

Nightscout only guarantees the CGM and treatment dates comply with ISO 8601 and can be both normalised to UTC or use the local time zoned format, with or without millisecond precision.

This is a bit of information I was looking for. I see two issues with this implementation:

  • I assume the date starts with the %Y-%M-%DT%H:%M:%S format
  • I assumed no timezone (ends with Z)

I imagine there is no way to cover what Nightscout could update with jq, and it needs a really smart parser. Would you see it reasonable to try with jq first, then to fallback on node json?
Note that jq can use strptime and strftime since jqlang/jq@a4b9552

Performance is a big concern to me, the pi0 spends all its time at 1000Mhz and loop times aren't ideal.
PS: Thanks for reviewing this in time though, @sulkaharo. Would have sucked to break parsing for other CGMs.

@sulkaharo
Copy link
Collaborator

Ok, so thinking about this, what we could do is have the code that loads the treatments from Nightscout translate the dates to whatever format Openaps wants to use internally and then have the scripts that need to be as performant as possible to use that format. This will probably slow down the data load from Nightscout, but would allow the rest of the code to trust the date formats. For this, what’s the ideal internal format? We could probably speed things up even more by using something like Javascript’s milliseconds from 1980 ( Date.now() ) which would be inherently compatible with what the oref JavaScript code does as well

@Dune-jr
Copy link
Author

Dune-jr commented Jan 3, 2020

@sulkaharo Sounds like a good way to go about it to me. If there is a need for retro-compatibility (which surely there is?), what about an additional timestamp field that gives this "Javascript’s milliseconds from 1980", besides the raw time format that we now store? This way, OpenAPS and other scripts could check whether this field is present, and do easy computations, or fallback on interpreting the raw data.

Unless you see a way to go about it that does not need backwards compatibility.

@tzachi-dar
Copy link
Contributor

If we go with global solution to #1348 than no need to contine here. On the other hand, if we don't than do it, by all means...

@Dune-jr
Copy link
Author

Dune-jr commented Jan 5, 2020

@tzachi-dar 100% agree

@tzachi-dar
Copy link
Contributor

Just to make sure we are all aligned up here:

This PR wanted to replace two parts of the code:

  1. json -c "minAgo=(new Date()-new Date(this.dateString))/60/1000; return minAgo < 10 && minAgo > -5 && this.glucose > 38"
    This seems problematic with some time format, so it is replaced entirely in my pr.

  2. json -f upload/latest-treatments.json -a created_at eventType
    This seems to be correct (no one complained) and I have thoroughly tested it on my pr. It is used as is.

Both of this exists in #1352

Please let me know if anyone sees a problem with this approach.

@jimrandomh
Copy link
Contributor

I believe this is probably unnecessary given #1411 , since the root cause of json being slow is addressed there.

@scottleibrand
Copy link
Contributor

If no objections, I'll close this as fixed by #1411, and we can follow up with #1370 if it's still needed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants