SASC: too many refreshes under the hood

osrf-migration commented 7 years ago

Original report (archived issue) by Hugo Boyer (Bitbucket: hugomatic, GitHub: hugomatic).

The following info shows the result of the node log tail -f /var/log/nodejs/nodejs.log that result from user interaction on the sasc kiosk.

The log format could be better (there's a response time but no date, I will be fixing that shortly). In general, these calls are often happening one after the other.

user action: CREATE ROUND

#!js

GET /simulators 304 12.488 ms - -
POST /sshkeys 200 256.805 ms - 142
POST /sshkeys 200 320.034 ms - 139
GET /simulators 304 12.907 ms - -
POST /sshkeys 200 353.561 ms - 139
POST /permissions 200 39.372 ms - 206
GET /simulators 304 9.336 ms - -
POST /permissions 200 19.820 ms - 206
POST /permissions 200 18.758 ms - 206
GET /simulators 304 9.247 ms - -
GET /simulators 304 9.233 ms - -
GET /simulators 304 9.196 ms - -
GET /simulators 304 9.284 ms - -
GET /simulators 304 9.177 ms - -
GET /simulators 304 9.315 ms - -
GET /simulators 304 9.248 ms - -
GET /simulators 304 9.221 ms - -
GET /simulators 304 10.602 ms - -
GET /simulators 304 9.220 ms - -
GET /simulators 304 9.309 ms - -
GET /simulators 304 9.258 ms - -
GET /simulators 304 10.347 ms - -
GET /simulators 304 9.237 ms - -
GET /simulators 304 10.039 ms - -
GET /simulators 304 9.239 ms - -
GET /simulators 304 9.257 ms - -
GET /simulators 304 9.235 ms - -
GET /simulators 304 9.287 ms - -
GET /simulators 304 9.270 ms - -
GET /simulators 304 11.124 ms - -
GET /simulators 304 9.584 ms - -
GET /simulators 304 9.264 ms - -
GET /simulators 304 9.321 ms - -
GET /simulators 304 9.637 ms - -
GET /simulators 304 9.217 ms - -
GET /simulators 304 11.172 ms - -
GET /simulators 304 9.258 ms - -
GET /simulators 304 9.231 ms - -
GET /simulators 304 9.289 ms - -
GET /simulators 304 9.241 ms - -
GET /simulators 304 9.232 ms - -
GET /simulators 304 10.309 ms - -
GET /simulators 304 9.191 ms - -
GET /simulators 304 9.188 ms - -
GET /simulators 304 9.188 ms - -
GET /simulators 304 9.314 ms - -
GET /simulators 304 12.694 ms - -
GET /simulators 304 13.445 ms - -
GET /simulators 304 12.273 ms - -
GET /simulators 304 13.305 ms - -
GET /simulators 304 12.694 ms - -
GET /simulators 304 12.812 ms - -
GET /simulators 304 12.592 ms - -
GET /simulators 304 14.702 ms - -
GET /simulators 304 12.235 ms - -

user action: LAUNCH ARBITER

#!js

Launching simulator
- region:us-west-1
- SSH key: sshkey-051
- hardware: c4.xlarge
- security: cloudsim-sim
- image: ami-fe99c49e
- tags: { Name: 'simulator-524_hugo@osrfoundation.org' }
- script size:2922

GET /simulators 200 9.912 ms - 263977
GET /simulators 304 11.639 ms - -
GET /simulators 304 9.232 ms - -
GET /simulators 304 9.223 ms - -
GET /simulators 304 9.324 ms - -
simulator-524 launch!
POST /simulators 200 1984.546 ms - 1294
GET /simulators 200 9.378 ms - 263996
POST /permissions 200 18.453 ms - 212
GET /simulators 200 10.771 ms - 264093
GET /simulators 304 9.283 ms - -
GET /simulators 304 9.261 ms - -
GET /simulators 304 9.327 ms - -
GET /simulators 304 12.920 ms - -
GET /simulators 304 13.494 ms - -
GET /simulators 304 12.214 ms - -
GET /simulators 304 13.546 ms - -
GET /simulators 304 12.647 ms - -
simulator-524 ip: 54.219.161.136
GET /simulators 200 21.153 ms - 264107
GET /simulators 304 9.461 ms - -
GET /simulators 304 9.360 ms - -
GET /simulators 304 9.362 ms - -
GET /simulators 304 9.320 ms - -
i-082a967da8761cf10 simulator-524 status update LAUNCHING => RUNNING
GET /simulators 200 9.322 ms - 264105
GET /simulators 304 9.281 ms - -
GET /simulators 304 12.866 ms - -
GET /simulators 304 12.844 ms - -
GET /simulators 304 12.266 ms - -

user action LAUNCH ALL BLUE PAYLOADS (1 machine):

#!js

Launching simulator
- region:us-west-1
- SSH key: sshkey-050
- hardware: m4.xlarge
- security: cloudsim-sim
- image: ami-fe99c49e
- tags: { Name: 'simulator-525_hugo@osrfoundation.org' }
- script size:3139

GET /simulators 200 15.681 ms - 265583
GET /simulators 304 14.949 ms - -
GET /simulators 304 14.345 ms - -
GET /simulators 304 14.593 ms - -
GET /simulators 304 12.648 ms - -
simulator-525 launch!
POST /simulators 200 1601.495 ms - 1377
GET /simulators 200 9.608 ms - 265602
POST /permissions 200 20.639 ms - 212
GET /simulators 200 9.538 ms - 265699
GET /simulators 304 9.431 ms - -
GET /simulators 304 10.168 ms - -
GET /simulators 304 14.714 ms - -
GET /simulators 304 12.828 ms - -
GET /simulators 304 12.323 ms - -
GET /simulators 304 14.306 ms - -
GET /simulators 304 13.000 ms - -
GET /simulators 304 13.024 ms - -
simulator-525 ip: 54.215.249.247
GET /simulators 200 9.548 ms - 265713
GET /simulators 304 9.353 ms - -
GET /simulators 304 10.784 ms - -
GET /simulators 304 9.265 ms - -
GET /simulators 304 9.301 ms - -
/tmp/cloudsim.pem written
cd /tmp && chmod 600 cloudsim.pem  && zip keys.zip cloudsim.pem
"/tmp/keys.zip" downloaded
GET /sshkeys/sshkey-051 200 12.389 ms - 1461
i-0343d9269bf8d878e simulator-525 status update LAUNCHING => RUNNING
GET /simulators 200 13.293 ms - 265711
GET /simulators 304 14.757 ms - -
GET /simulators 304 13.586 ms - -
GET /simulators 304 13.128 ms - -
GET /simulators 304 13.986 ms - -

user action: FINISH ROUND

#!js

simulator-525 terminate
DELETE /simulators/simulator-525 200 348.881 ms - 1618
DELETE /sshkeys/sshkey-051 200 358.669 ms - 16
DELETE /sshkeys/sshkey-050 200 304.737 ms - 16
simulator-526 terminate
DELETE /simulators/simulator-526 200 414.985 ms - 1615
simulator-524 terminate
DELETE /simulators/simulator-524 200 428.941 ms - 1535
DELETE /sshkeys/sshkey-052 200 245.215 ms - 16
GET /simulators 200 15.907 ms - 267353
GET /simulators 304 14.044 ms - -
GET /simulators 304 13.680 ms - -
GET /simulators 304 13.499 ms - -
GET /simulators 304 13.370 ms - -
GET /simulators 304 12.929 ms - -
GET /simulators 304 15.622 ms - -
GET /simulators 304 12.749 ms - -
GET /simulators 304 23.604 ms - -
GET /simulators 304 9.495 ms - -
GET /simulators 304 9.300 ms - -
GET /simulators 304 9.438 ms - -
GET /simulators 304 9.541 ms - -
GET /simulators 304 10.968 ms - -
GET /simulators 304 9.440 ms - -
GET /simulators 304 12.807 ms - -
GET /simulators 304 12.997 ms - -
GET /simulators 304 13.403 ms - -
GET /simulators 304 14.202 ms - -
GET /simulators 304 13.063 ms - -
GET /simulators 304 13.229 ms - -
GET /simulators 304 12.776 ms - -
GET /simulators 304 12.475 ms - -
GET /simulators 304 13.072 ms - -
GET /simulators 304 27.744 ms - -
GET /simulators 304 11.049 ms - -
GET /simulators 304 10.694 ms - -
GET /simulators 304 10.774 ms - -
GET /simulators 304 11.166 ms - -
GET /simulators 304 10.739 ms - -

If you eliminate a few refreshes (launching->running, find the ip), there are still a lot of unnecessary calls. Also, these calls used to be very slow (when the database was on a t2.micro).

Because we are using REST, PUT calls contain the whole state for each update, and the database incurs many writes.

The problem may be due to:

too many updates (each update triggers a refresh of the whole collection)
a websocket error (multiple updates per connected client)

Solutions may include:

delaying a refresh for a time, to collapse many refreshes into "one at most 0.x seconds")
reducing the round data updates
look for a problem in the "data binding callbacks"

osrf-migration commented 7 years ago

Original comment by Hugo Boyer (Bitbucket: hugomatic, GitHub: hugomatic).

After a quick investigation with @chapulina, we decided to instrument the websocket events.

Since the sasc round is creating a lot of new resources on the portal (3 ssh keys, multiple machines), and each can trigger multiple updates. It's also interesting that a lot of those calls are 304 redirects, and I will try to understand how these work.

The logging output is to be customize to better understand the delays between the calls.

osrf-migration commented 7 years ago

Original comment by Hugo Boyer (Bitbucket: hugomatic, GitHub: hugomatic).

osrf-migration commented 7 years ago

Original comment by Hugo Boyer (Bitbucket: hugomatic, GitHub: hugomatic).

https://osrf-migration.github.io/osrf-archived-gh-pages/#!/osrf/cloudsim-widgets/pull-requests/121/extra-sasc-calls/diff

osrf-migration commented 7 years ago

Original comment by Louise Poubel (Bitbucket: chapulina, GitHub: chapulina).

set component to "SASC"

osrf-migration commented 7 years ago

Original comment by Louise Poubel (Bitbucket: chapulina, GitHub: chapulina).

changed state from "new" to "wontfix"

SASC is over

osrf / cloudsim-widgets

SASC: too many refreshes under the hood #42