{"action":"created","issue":{"url":"https://api.github.com/repos/e-mission/e-mission-docs/issues/488","repository_url":"https://api.github.com/repos/e-mission/e-mission-docs","labels_url":"https://api.github.com/repos/e-mission/e-mission-docs/issues/488/labels{/name}","comments_url":"https://api.github.com/repos/e-mission/e-mission-docs/issues/488/comments","events_url":"https://api.github.com/repos/e-mission/e-mission-docs/issues/488/events","html_url":"https://github.com/e-mission/e-mission-docs/issues/488","id":544526051,"node_id":"MDU6SXNzdWU1NDQ1MjYwNTE=","number":488,"title":"Slow loading on diary list page","user":{"login":"atton16","id":5247367,"node_id":"MDQ6VXNlcjUyNDczNjc=","avatar_url":"https://avatars1.githubusercontent.com/u/5247367?v=4","gravatar_id":"","url":"https://api.github.com/users/atton16","html_url":"https://github.com/atton16","followers_url":"https://api.github.com/users/atton16/followers","following_url":"https://api.github.com/users/atton16/following{/other_user}","gists_url":"https://api.github.com/users/atton16/gists{/gist_id}","starred_url":"https://api.github.com/users/atton16/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/atton16/subscriptions","organizations_url":"https://api.github.com/users/atton16/orgs","repos_url":"https://api.github.com/users/atton16/repos","events_url":"https://api.github.com/users/atton16/events{/privacy}","received_events_url":"https://api.github.com/users/atton16/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":13,"created_at":"2020-01-02T10:36:53Z","updated_at":"2020-01-08T21:10:01Z","closed_at":null,"author_association":"NONE","body":"We have discovered loading trips for one day is fairly slow. At the moment, we only have 2000 trips from 2 users and loading time went to about 7-10 seconds.\r\n\r\nThe log below comes from `e-mission-phone` instance.\r\n\r\nI tried to timed it with the program to get the sense of time.\r\nHere we print out 2 `TEST_TIMESTAMP: <ts>`.\r\nThe first one is printed right after the user pick the date.\r\nThe latter one printed right after `About to hide 'Processing trips'` printed.\r\n\r\nHere is what we got\r\n```\r\n1. TEST_TIMESTAMP: 1577960578513\r\n2. TEST_TIMESTAMP: 1577960585710\r\n```\r\n\r\nIn total, it takes about `7.2` seconds (7,197 ms) to load the day.\r\n\r\nOn the server, it takes about `3.461620569229126` seconds.\r\n\r\nWhich means after the phone got data from server, we need to wait for it to process data for about `3.5` seconds.\r\n\r\nThe loading got worse when we take into account the network conditions.\r\n\r\nI am not certain how to deal with this situation to reduce to loading time to sub 4 seconds.\r\n\r\nPlease advice.\r\n\r\nFull `e-mission-server` log\r\n```\r\nSTART 2020-01-02 10:22:11.073440 POST /timeline/getTrips/2019-12-11\r\nSTART 2020-01-02 10:22:11.086699 POST /pipeline/get_complete_ts\r\nEND 2020-01-02 10:22:11.089228 POST /pipeline/get_complete_ts 74fc6ede-ece0-43b5-ade3-456ebe034e3f 0.0024852752685546875 \r\nSTART 2020-01-02 10:22:11.106867 POST /datastreams/find_entries/timestamp\r\nSTART 2020-01-02 10:22:11.127280 POST /datastreams/find_entries/timestamp\r\nSTART 2020-01-02 10:22:11.138953 POST /datastreams/find_entries/timestamp\r\nEND 2020-01-02 10:22:11.140906 POST /datastreams/find_entries/timestamp 74fc6ede-ece0-43b5-ade3-456ebe034e3f 0.0019130706787109375 \r\nEND 2020-01-02 10:22:11.571569 POST /datastreams/find_entries/timestamp 74fc6ede-ece0-43b5-ade3-456ebe034e3f 0.46465229988098145 \r\nEND 2020-01-02 10:22:11.604497 POST /datastreams/find_entries/timestamp 74fc6ede-ece0-43b5-ade3-456ebe034e3f 0.4771711826324463 \r\nEND 2020-01-02 10:22:14.535112 POST /timeline/getTrips/2019-12-11 74fc6ede-ece0-43b5-ade3-456ebe034e3f 3.461620569229126 \r\n```\r\n\r\nFull `e-mission-phone` log\r\n[emp-2020-01-02.log](https://gist.github.com/atton16/5567c86c7ce5f4f0c4d08c657e1314c8)"},"comment":{"url":"https://api.github.com/repos/e-mission/e-mission-docs/issues/comments/572258138","html_url":"https://github.com/e-mission/e-mission-docs/issues/488#issuecomment-572258138","issue_url":"https://api.github.com/repos/e-mission/e-mission-docs/issues/488","id":572258138,"node_id":"MDEyOklzc3VlQ29tbWVudDU3MjI1ODEzOA==","user":{"login":"asiripanich","id":17020181,"node_id":"MDQ6VXNlcjE3MDIwMTgx","avatar_url":"https://avatars3.githubusercontent.com/u/17020181?v=4","gravatar_id":"","url":"https://api.github.com/users/asiripanich","html_url":"https://github.com/asiripanich","followers_url":"https://api.github.com/users/asiripanich/followers","following_url":"https://api.github.com/users/asiripanich/following{/other_user}","gists_url":"https://api.github.com/users/asiripanich/gists{/gist_id}","starred_url":"https://api.github.com/users/asiripanich/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/asiripanich/subscriptions","organizations_url":"https://api.github.com/users/asiripanich/orgs","repos_url":"https://api.github.com/users/asiripanich/repos","events_url":"https://api.github.com/users/asiripanich/events{/privacy}","received_events_url":"https://api.github.com/users/asiripanich/received_events","type":"User","site_admin":false},"created_at":"2020-01-08T21:10:01Z","updated_at":"2020-01-08T21:10:01Z","author_association":"NONE","body":"> I focused on the logs for the `/timeline/getTrips/2019-12-11` call, which took 7 seconds on the server (`09:56:42` -> `09:56:49`). The details are below, but I think that the reason for the variety of response times that we are seeing is that the call is O(nSections), not O(nUsers) or O(nDays).\r\n> \r\n> To rephrase, the main determinant of the response time is not the database access time, which is ~ 26 ms (`09:56:42,886` -> `09:56:42,912`), but the processing time to convert the retrieved values to the geojson format for the client.\r\n> \r\n> The particular day that you were retrieving had 7 trips with 11 sections.\r\n> \r\n> ```\r\n> 2020-01-02 09:56:42,890:DEBUG:140518462981888:finished querying values for ['analysis/cleaned_trip', 'analysis/cleaned_untracked'], count = 7\r\n> ...\r\n> $ grep \"mapped cleaned section\" /tmp/webserver_log_gettrips | wc -l\r\n>       11\r\n> ```\r\n> \r\n> A simpler day with fewer trips (e.g. unimodal commute to/from work) should be much faster.\r\n> \r\n> @asiripanich @atton16 In parallel with this investigation, can you try with a simpler day and confirm that the load time is much faster?\r\n\r\nWe recently started a fresh database to prepare for our upcoming deployment so the loading time now is more acceptable (4 ~ 5 s) on days with 6-8 trips. \r\n"}}
{"actor":{"display_login":"asiripanich"}}