search

e-mission / e-mission-docs

Repository for docs and issues. If you need help, please file an issue here. Public conversations are better for open source projects than private email.
https://e-mission.readthedocs.io/en/latest
BSD 3-Clause "New" or "Revised" License
15 stars 34 forks source link

Slow loading on diary list page #488

Closed atton16 closed 4 years ago

atton16 commented 4 years ago

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.

The log below comes from e-mission-phone instance.

I tried to timed it with the program to get the sense of time. Here we print out 2 TEST_TIMESTAMP: <ts>. The first one is printed right after the user pick the date. The latter one printed right after About to hide 'Processing trips' printed.

Here is what we got

1. TEST_TIMESTAMP: 1577960578513
2. TEST_TIMESTAMP: 1577960585710

In total, it takes about 7.2 seconds (7,197 ms) to load the day.

On the server, it takes about 3.461620569229126 seconds.

Which means after the phone got data from server, we need to wait for it to process data for about 3.5 seconds.

The loading got worse when we take into account the network conditions.

I am not certain how to deal with this situation to reduce to loading time to sub 4 seconds.

Please advice.

Full e-mission-server log

START 2020-01-02 10:22:11.073440 POST /timeline/getTrips/2019-12-11
START 2020-01-02 10:22:11.086699 POST /pipeline/get_complete_ts
END 2020-01-02 10:22:11.089228 POST /pipeline/get_complete_ts 74fc6ede-ece0-43b5-ade3-456ebe034e3f 0.0024852752685546875 
START 2020-01-02 10:22:11.106867 POST /datastreams/find_entries/timestamp
START 2020-01-02 10:22:11.127280 POST /datastreams/find_entries/timestamp
START 2020-01-02 10:22:11.138953 POST /datastreams/find_entries/timestamp
END 2020-01-02 10:22:11.140906 POST /datastreams/find_entries/timestamp 74fc6ede-ece0-43b5-ade3-456ebe034e3f 0.0019130706787109375 
END 2020-01-02 10:22:11.571569 POST /datastreams/find_entries/timestamp 74fc6ede-ece0-43b5-ade3-456ebe034e3f 0.46465229988098145 
END 2020-01-02 10:22:11.604497 POST /datastreams/find_entries/timestamp 74fc6ede-ece0-43b5-ade3-456ebe034e3f 0.4771711826324463 
END 2020-01-02 10:22:14.535112 POST /timeline/getTrips/2019-12-11 74fc6ede-ece0-43b5-ade3-456ebe034e3f 3.461620569229126

Full e-mission-phone log emp-2020-01-02.log

shankari commented 4 years ago

At the moment, we only have 2000 trips from 2 users and loading time went to about 7-10 seconds.

This is almost certainly not related to the number of users or objects because the calls to retrieve the entries are almost instantaneous - e.g.

START 2020-01-02 10:22:11.106867 POST /datastreams/find_entries/timestamp
END 2020-01-02 10:22:11.140906 POST /datastreams/find_entries/timestamp 74fc6ede-ece0-43b5-ade3-456ebe034e3f 0.0019130706787109375

You can check the detailed webserver logs to confirm this. The main time appears to be spent in processing the data, both on the server 

START 2020-01-02 10:22:11.073440 POST /timeline/getTrips/2019-12-11
END 2020-01-02 10:22:14.535112 POST /timeline/getTrips/2019-12-11 74fc6ede-ece0-43b5-ade3-456ebe034e3f 3.461620569229126

and on the phone (the additional 3.5 seconds).

Let's start on the server. Can you look at the detailed logs for the /timeline/getTrips/2019-12-11 operation and figure out how long each component is taking?

atton16 commented 4 years ago

Not sure if this is the right one.

I found this log in ${EMISSION_SERVER_LOG_FDIR}/tmp/tmp/webserver.log

2020-01-02 09:56:42,749:DEBUG:140518462981888:START POST /timeline/getTrips/2019-12-11
2020-01-02 09:56:42,749:DEBUG:140518462981888:Called timeline.getTrips/2019-12-11
2020-01-02 09:56:42,749:DEBUG:140518462981888:methodName = google_auth, returning <class 'emission.net.auth.google_auth.GoogleAuthMethod'>
2020-01-02 09:56:42,749:DEBUG:140518462981888:Using the google auth library to verify id token of length 917 from android phones
2020-01-02 09:56:42,750:DEBUG:140518462981888:Making request: GET https://www.googleapis.com/oauth2/v1/certs
2020-01-02 09:56:42,777:DEBUG:140518454589184:START POST /datastreams/find_entries/timestamp
2020-01-02 09:56:42,777:DEBUG:140518454589184:methodName = google_auth, returning <class 'emission.net.auth.google_auth.GoogleAuthMethod'>
2020-01-02 09:56:42,777:DEBUG:140518454589184:Using the google auth library to verify id token of length 917 from android phones
2020-01-02 09:56:42,778:DEBUG:140518454589184:Making request: GET https://www.googleapis.com/oauth2/v1/certs
2020-01-02 09:56:42,789:DEBUG:140518488160000:START POST /pipeline/get_complete_ts
2020-01-02 09:56:42,789:DEBUG:140518488160000:methodName = google_auth, returning <class 'emission.net.auth.google_auth.GoogleAuthMethod'>
2020-01-02 09:56:42,789:DEBUG:140518488160000:Using the google auth library to verify id token of length 917 from android phones
2020-01-02 09:56:42,789:DEBUG:140518488160000:Making request: GET https://www.googleapis.com/oauth2/v1/certs
2020-01-02 09:56:42,791:DEBUG:140518504945408:START POST /datastreams/find_entries/timestamp
2020-01-02 09:56:42,792:DEBUG:140518504945408:methodName = google_auth, returning <class 'emission.net.auth.google_auth.GoogleAuthMethod'>
2020-01-02 09:56:42,792:DEBUG:140518504945408:Using the google auth library to verify id token of length 917 from android phones
2020-01-02 09:56:42,792:DEBUG:140518504945408:Making request: GET https://www.googleapis.com/oauth2/v1/certs
2020-01-02 09:56:42,798:DEBUG:140517975258880:START POST /datastreams/find_entries/timestamp
2020-01-02 09:56:42,798:DEBUG:140517975258880:methodName = google_auth, returning <class 'emission.net.auth.google_auth.GoogleAuthMethod'>
2020-01-02 09:56:42,799:DEBUG:140517975258880:Using the google auth library to verify id token of length 917 from android phones
2020-01-02 09:56:42,799:DEBUG:140517975258880:Making request: GET https://www.googleapis.com/oauth2/v1/certs
2020-01-02 09:56:42,876:DEBUG:140518462981888:tokenFields from library = {'iss': 'https://accounts.google.com', 'azp': '97387382925-caup6t5g8fho7d7ctf78d8l9f4avre4p.apps.googleusercontent.com', 'aud': '97387382925-caup6t5g8fho7d7ctf78d8l9f4avre4p.apps.googleusercontent.com', 'sub': '103282700801490462372', 'email': 'rciti.emission@gmail.com', 'email_verified': True, 'at_hash': 'Ei0Tsqsg9XBddbOQbqtRzA', 'iat': 1577958670, 'exp': 1577962270}
2020-01-02 09:56:42,877:DEBUG:140518462981888:Found user email rciti.emission@gmail.com
2020-01-02 09:56:42,878:DEBUG:140518462981888:retUUID = 74fc6ede-ece0-43b5-ade3-456ebe034e3f
2020-01-02 09:56:42,878:DEBUG:140518462981888:user_uuid 74fc6ede-ece0-43b5-ade3-456ebe034e3f
2020-01-02 09:56:42,878:DEBUG:140518462981888:Getting geojson for LocalDate({'year': 2019, 'month': 12, 'day': 11}) -> LocalDate({'year': 2019, 'month': 12, 'day': 11})
2020-01-02 09:56:42,878:INFO:140518462981888:About to query for date components LocalDate({'year': 2019, 'month': 12, 'day': 11}) -> LocalDate({'year': 2019, 'month': 12, 'day': 11})
2020-01-02 09:56:42,878:DEBUG:140518462981888:for user 74fc6ede-ece0-43b5-ade3-456ebe034e3f, returning timeseries <emission.storage.timeseries.builtin_timeseries.BuiltinTimeSeries object at 0x7fcce2d78fd0>
2020-01-02 09:56:42,878:DEBUG:140518462981888:In get_range_query, returning query {'data.enter_local_dt.year': {'$gte': 2019, '$lte': 2019}, 'data.enter_local_dt.month': {'$gte': 12, '$lte': 12}, 'data.enter_local_dt.day': {'$gte': 11, '$lte': 11}}
2020-01-02 09:56:42,879:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/cleaned_place'}], 'data.enter_local_dt.year': {'$gte': 2019, '$lte': 2019}, 'data.enter_local_dt.month': {'$gte': 12, '$lte': 12}, 'data.enter_local_dt.day': {'$gte': 11, '$lte': 11}}, sort_key = data.enter_ts
2020-01-02 09:56:42,879:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/cleaned_place']
2020-01-02 09:56:42,880:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:42,880:DEBUG:140518462981888:In get_range_query, returning query {'data.enter_local_dt.year': {'$gte': 2019, '$lte': 2019}, 'data.enter_local_dt.month': {'$gte': 12, '$lte': 12}, 'data.enter_local_dt.day': {'$gte': 11, '$lte': 11}}
2020-01-02 09:56:42,881:DEBUG:140518462981888:finished querying values for ['analysis/cleaned_place'], count = 6
2020-01-02 09:56:42,883:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 6
2020-01-02 09:56:42,886:DEBUG:140518462981888:Returning entry with length 6 result
2020-01-02 09:56:42,886:DEBUG:140518462981888:for user 74fc6ede-ece0-43b5-ade3-456ebe034e3f, returning timeseries <emission.storage.timeseries.builtin_timeseries.BuiltinTimeSeries object at 0x7fcce2d78fd0>
2020-01-02 09:56:42,886:DEBUG:140518462981888:after appending untracked_key analysis/cleaned_untracked, key_list is ['analysis/cleaned_trip', 'analysis/cleaned_untracked']
2020-01-02 09:56:42,886:DEBUG:140518462981888:In get_range_query, returning query {'data.start_local_dt.year': {'$gte': 2019, '$lte': 2019}, 'data.start_local_dt.month': {'$gte': 12, '$lte': 12}, 'data.start_local_dt.day': {'$gte': 11, '$lte': 11}}
2020-01-02 09:56:42,886:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/cleaned_trip'}, {'metadata.key': 'analysis/cleaned_untracked'}], 'data.start_local_dt.year': {'$gte': 2019, '$lte': 2019}, 'data.start_local_dt.month': {'$gte': 12, '$lte': 12}, 'data.start_local_dt.day': {'$gte': 11, '$lte': 11}}, sort_key = data.start_ts
2020-01-02 09:56:42,887:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/cleaned_trip', 'analysis/cleaned_untracked']
2020-01-02 09:56:42,887:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:42,887:DEBUG:140518462981888:In get_range_query, returning query {'data.start_local_dt.year': {'$gte': 2019, '$lte': 2019}, 'data.start_local_dt.month': {'$gte': 12, '$lte': 12}, 'data.start_local_dt.day': {'$gte': 11, '$lte': 11}}
2020-01-02 09:56:42,890:DEBUG:140518462981888:finished querying values for ['analysis/cleaned_trip', 'analysis/cleaned_untracked'], count = 7
2020-01-02 09:56:42,894:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 7
2020-01-02 09:56:42,910:DEBUG:140518454589184:tokenFields from library = {'iss': 'https://accounts.google.com', 'azp': '97387382925-caup6t5g8fho7d7ctf78d8l9f4avre4p.apps.googleusercontent.com', 'aud': '97387382925-caup6t5g8fho7d7ctf78d8l9f4avre4p.apps.googleusercontent.com', 'sub': '103282700801490462372', 'email': 'rciti.emission@gmail.com', 'email_verified': True, 'at_hash': 'Ei0Tsqsg9XBddbOQbqtRzA', 'iat': 1577958670, 'exp': 1577962270}
2020-01-02 09:56:42,910:DEBUG:140518454589184:Found user email rciti.emission@gmail.com
2020-01-02 09:56:42,912:DEBUG:140518462981888:Returning entry with length 7 result
2020-01-02 09:56:42,912:DEBUG:140518462981888:Considering place 5df031aaea7b5e470afa4bcb: 2019-12-11T08:39:40.698044+11:00 -> 2019-12-11T09:01:57.246713+11:00 
2020-01-02 09:56:42,912:DEBUG:140518462981888:Considering place 5df031aaea7b5e470afa4bcc: 2019-12-11T09:15:11.411832+11:00 -> 2019-12-11T09:16:23.545058+11:00 
2020-01-02 09:56:42,912:DEBUG:140518462981888:Considering place 5df0343aea7b5e4729725b7c: 2019-12-11T11:00:35.047432+11:00 -> 2019-12-11T11:55:54.679161+11:00 
2020-01-02 09:56:42,913:DEBUG:140518462981888:Considering place 5dfabdb6ea7b5e0054548ed8: 2019-12-11T12:23:22.674427+11:00 -> 2019-12-11T13:09:57.016451+11:00 
2020-01-02 09:56:42,913:DEBUG:140518462981888:Considering place 5dfabdb6ea7b5e0054548ed9: 2019-12-11T13:34:23.737500+11:00 -> 2019-12-11T14:28:55.079099+11:00 
2020-01-02 09:56:42,913:DEBUG:140518462981888:Considering place 5dfabdb6ea7b5e0054548eda: 2019-12-11T15:32:17.742592+11:00 -> 2019-12-11T15:32:17.742592+11:00 
2020-01-02 09:56:42,913:DEBUG:140518462981888:Considering trip 5df031a9ea7b5e470afa4b85: 2019-12-11T08:26:07.045904+11:00 -> 2019-12-11T08:39:40.698044+11:00 
2020-01-02 09:56:42,914:DEBUG:140518462981888:Considering trip 5df031a9ea7b5e470afa4ba5: 2019-12-11T09:01:57.246713+11:00 -> 2019-12-11T09:15:11.411832+11:00 
2020-01-02 09:56:42,920:DEBUG:140518454589184:retUUID = 74fc6ede-ece0-43b5-ade3-456ebe034e3f
2020-01-02 09:56:42,929:DEBUG:140518462981888:Considering trip 5df03438ea7b5e4729725aa3: 2019-12-11T09:16:23.545058+11:00 -> 2019-12-11T11:00:35.047432+11:00 
2020-01-02 09:56:42,941:DEBUG:140518462981888:Considering trip 5dfabdb3ea7b5e0054548de2: 2019-12-11T11:55:54.679161+11:00 -> 2019-12-11T12:23:22.674427+11:00 
2020-01-02 09:56:42,942:DEBUG:140518504945408:tokenFields from library = {'iss': 'https://accounts.google.com', 'azp': '97387382925-caup6t5g8fho7d7ctf78d8l9f4avre4p.apps.googleusercontent.com', 'aud': '97387382925-caup6t5g8fho7d7ctf78d8l9f4avre4p.apps.googleusercontent.com', 'sub': '103282700801490462372', 'email': 'rciti.emission@gmail.com', 'email_verified': True, 'at_hash': 'Ei0Tsqsg9XBddbOQbqtRzA', 'iat': 1577958670, 'exp': 1577962270}
2020-01-02 09:56:42,956:DEBUG:140518504945408:Found user email rciti.emission@gmail.com
2020-01-02 09:56:42,946:DEBUG:140518488160000:tokenFields from library = {'iss': 'https://accounts.google.com', 'azp': '97387382925-caup6t5g8fho7d7ctf78d8l9f4avre4p.apps.googleusercontent.com', 'aud': '97387382925-caup6t5g8fho7d7ctf78d8l9f4avre4p.apps.googleusercontent.com', 'sub': '103282700801490462372', 'email': 'rciti.emission@gmail.com', 'email_verified': True, 'at_hash': 'Ei0Tsqsg9XBddbOQbqtRzA', 'iat': 1577958670, 'exp': 1577962270}
2020-01-02 09:56:42,945:DEBUG:140518462981888:Considering trip 5dfabdb4ea7b5e0054548e1f: 2019-12-11T13:09:57.016451+11:00 -> 2019-12-11T13:34:23.737500+11:00 
2020-01-02 09:56:42,961:DEBUG:140517975258880:tokenFields from library = {'iss': 'https://accounts.google.com', 'azp': '97387382925-caup6t5g8fho7d7ctf78d8l9f4avre4p.apps.googleusercontent.com', 'aud': '97387382925-caup6t5g8fho7d7ctf78d8l9f4avre4p.apps.googleusercontent.com', 'sub': '103282700801490462372', 'email': 'rciti.emission@gmail.com', 'email_verified': True, 'at_hash': 'Ei0Tsqsg9XBddbOQbqtRzA', 'iat': 1577958670, 'exp': 1577962270}
2020-01-02 09:56:42,961:DEBUG:140518454589184:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/mode_confirm'}], 'metadata.write_ts': {'$lte': 1577959001.594, '$gte': 0}}, sort_key = metadata.write_ts
2020-01-02 09:56:42,961:DEBUG:140518488160000:Found user email rciti.emission@gmail.com
2020-01-02 09:56:42,962:DEBUG:140518504945408:retUUID = 74fc6ede-ece0-43b5-ade3-456ebe034e3f
2020-01-02 09:56:42,962:DEBUG:140518462981888:Considering trip 5dfabdb5ea7b5e0054548e55: 2019-12-11T14:28:55.079099+11:00 -> 2019-12-11T15:32:17.742592+11:00 
2020-01-02 09:56:42,963:DEBUG:140517975258880:Found user email rciti.emission@gmail.com
2020-01-02 09:56:42,963:DEBUG:140518454589184:orig_ts_db_keys = ['manual/mode_confirm'], analysis_ts_db_keys = []
2020-01-02 09:56:42,965:DEBUG:140517975258880:retUUID = 74fc6ede-ece0-43b5-ade3-456ebe034e3f
2020-01-02 09:56:42,966:DEBUG:140518504945408:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/confirm_survey'}], 'metadata.write_ts': {'$lte': 1577959001.595, '$gte': 0}}, sort_key = metadata.write_ts
2020-01-02 09:56:42,967:DEBUG:140518462981888:Considering trip 5dfc0f15ea7b5e015419dfa0: 2019-12-11T15:32:17.742592+11:00 -> 2019-12-19T15:00:01.132341+11:00 
2020-01-02 09:56:42,967:DEBUG:140518488160000:retUUID = 74fc6ede-ece0-43b5-ade3-456ebe034e3f
2020-01-02 09:56:42,967:DEBUG:140518504945408:orig_ts_db_keys = ['manual/confirm_survey'], analysis_ts_db_keys = []
2020-01-02 09:56:42,968:DEBUG:140517975258880:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/purpose_confirm'}], 'metadata.write_ts': {'$lte': 1577959001.594, '$gte': 0}}, sort_key = metadata.write_ts
2020-01-02 09:56:42,968:DEBUG:140518462981888:keys = (analysis/cleaned_place, analysis/cleaned_trip), len(places) = 6, len(trips) = 7
2020-01-02 09:56:42,969:DEBUG:140518488160000:Returning complete_ts = 1577240145.99933
2020-01-02 09:56:42,969:DEBUG:140517975258880:orig_ts_db_keys = ['manual/purpose_confirm'], analysis_ts_db_keys = []
2020-01-02 09:56:42,970:DEBUG:140518462981888:places_or_stops = [ObjectId('5df031aaea7b5e470afa4bcb'), ObjectId('5df031aaea7b5e470afa4bcc'), ObjectId('5df0343aea7b5e4729725b7c'), ObjectId('5dfabdb6ea7b5e0054548ed8'), ObjectId('5dfabdb6ea7b5e0054548ed9'), ObjectId('5dfabdb6ea7b5e0054548eda')] 
2020-01-02 09:56:42,970:DEBUG:140518488160000:END POST /pipeline/get_complete_ts 74fc6ede-ece0-43b5-ade3-456ebe034e3f 0.18133211135864258 
2020-01-02 09:56:42,971:DEBUG:140518462981888:trips_or_sections = [ObjectId('5df031a9ea7b5e470afa4b85'), ObjectId('5df031a9ea7b5e470afa4ba5'), ObjectId('5df03438ea7b5e4729725aa3'), ObjectId('5dfabdb3ea7b5e0054548de2'), ObjectId('5dfabdb4ea7b5e0054548e1f'), ObjectId('5dfabdb5ea7b5e0054548e55'), ObjectId('5dfc0f15ea7b5e015419dfa0')] 
2020-01-02 09:56:42,971:DEBUG:140518462981888:to find start, comparing place 5df031aaea7b5e470afa4bcb with trip 5df031a9ea7b5e470afa4b85
2020-01-02 09:56:42,972:DEBUG:140518488160000:insert called with entry of type <class 'emission.core.wrapper.entry.Entry'>
2020-01-02 09:56:42,973:DEBUG:140518462981888:Starting with element of type trip, id 5df031a9ea7b5e470afa4b85, details Entry({'_id': ObjectId('5df031a9ea7b5e470afa4b85'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/cleaned_trip', 'platform': 'server', 'write_ts': 1576022441.5444167, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 0, 'second': 41, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:00:41.544417-08:00'}, 'data': {'source': 'DwellSegmentationDistFilter', 'end_ts': 1576013980.6980438, 'end_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 8, 'minute': 39, 'second': 40, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'end_fmt_time': '2019-12-11T08:39:40.698044+11:00', 'end_loc': {'type': 'Point', 'coordinates': [151.23954535866795, -33.9155451382473]}, 'raw_trip': ObjectId('5df031a7ea7b5e470afa4b38'), 'start_ts': 1576013167.0459037, 'start_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 8, 'minute': 26, 'second': 7, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'start_fmt_time': '2019-12-11T08:26:07.045904+11:00', 'start_loc': {'type': 'Point', 'coordinates': [151.23716632020535, -33.916413875805034]}, 'duration': 813.6521401405334, 'distance': 831.3409830943984, 'start_place': ObjectId('5df031aaea7b5e470afa4bca'), 'end_place': ObjectId('5df031aaea7b5e470afa4bcb')}})
2020-01-02 09:56:42,973:DEBUG:140518488160000:entry was fine, no need to fix it
2020-01-02 09:56:42,973:DEBUG:140518462981888:for trip = 5df031a9ea7b5e470afa4b85, adding start_place 5df031aaea7b5e470afa4bca and end_place 5df031aaea7b5e470afa4bcb
2020-01-02 09:56:42,973:DEBUG:140518488160000:Inserting entry Entry({'_id': ObjectId('5e0dbe5a4d2a1c000e34ac3d'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': Metadata({'key': 'stats/server_api_time', 'platform': 'server', 'write_ts': 1577959002.9712977, 'time_zone': 'America/Los_Angeles', 'write_local_dt': LocalDate({'year': 2020, 'month': 1, 'day': 2, 'hour': 1, 'minute': 56, 'second': 42, 'weekday': 3, 'timezone': 'America/Los_Angeles'}), 'write_fmt_time': '2020-01-02T01:56:42.971298-08:00'}), 'data': {'name': 'POST_/pipeline/get_complete_ts', 'ts': 1577959002.9704096, 'reading': 0.18133211135864258}}) into timeseries
2020-01-02 09:56:42,974:DEBUG:140518462981888:place id 5df031aaea7b5e470afa4bca is not in the map, searching in database
2020-01-02 09:56:42,976:DEBUG:140518488160000:insert called with entry of type <class 'emission.core.wrapper.entry.Entry'>
2020-01-02 09:56:42,976:DEBUG:140518488160000:entry was fine, no need to fix it
2020-01-02 09:56:42,977:DEBUG:140518462981888:retrieved object Entry({'_id': ObjectId('5df031aaea7b5e470afa4bca'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/cleaned_place', 'platform': 'server', 'write_ts': 1576022442.0511272, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 0, 'second': 42, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:00:42.051127-08:00'}, 'data': {'source': 'DwellSegmentationDistFilter', 'enter_ts': 1575967986.96997, 'enter_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 19, 'minute': 53, 'second': 6, 'weekday': 1, 'timezone': 'Australia/Sydney'}, 'enter_fmt_time': '2019-12-10T19:53:06.969970+11:00', 'location': {'type': 'Point', 'coordinates': [151.23716632020535, -33.916413875805034]}, 'raw_places': [ObjectId('5df031a7ea7b5e470afa4b37'), ObjectId('5df031a7ea7b5e470afa4b37')], 'ending_trip': ObjectId('5df031a9ea7b5e470afa4b7b'), 'starting_trip': ObjectId('5df031a9ea7b5e470afa4b85'), 'exit_ts': 1576013167.0459037, 'exit_fmt_time': '2019-12-11T08:26:07.045904+11:00', 'exit_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 8, 'minute': 26, 'second': 7, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'duration': 45180.07593369484}}) and added to id_map
2020-01-02 09:56:42,977:DEBUG:140518488160000:Inserting entry Entry({'_id': ObjectId('5e0dbe5a4d2a1c000e34ac3e'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': Metadata({'key': 'stats/server_api_time', 'platform': 'server', 'write_ts': 1577959002.9752688, 'time_zone': 'America/Los_Angeles', 'write_local_dt': LocalDate({'year': 2020, 'month': 1, 'day': 2, 'hour': 1, 'minute': 56, 'second': 42, 'weekday': 3, 'timezone': 'America/Los_Angeles'}), 'write_fmt_time': '2020-01-02T01:56:42.975269-08:00'}), 'data': {'name': 'POST_/pipeline/get_complete_ts_cputime', 'ts': 1577959002.9704096, 'reading': 0.18124613794498146}}) into timeseries
2020-01-02 09:56:42,977:DEBUG:140518462981888:for trip = 5df031a9ea7b5e470afa4ba5, adding start_place 5df031aaea7b5e470afa4bcb and end_place 5df031aaea7b5e470afa4bcc
2020-01-02 09:56:42,978:DEBUG:140518462981888:for trip = 5df03438ea7b5e4729725aa3, adding start_place 5df031aaea7b5e470afa4bcc and end_place 5df0343aea7b5e4729725b7c
2020-01-02 09:56:42,979:DEBUG:140518462981888:for trip = 5dfabdb3ea7b5e0054548de2, adding start_place 5df0343aea7b5e4729725b7c and end_place 5dfabdb6ea7b5e0054548ed8
2020-01-02 09:56:42,979:DEBUG:140518462981888:for trip = 5dfabdb4ea7b5e0054548e1f, adding start_place 5dfabdb6ea7b5e0054548ed8 and end_place 5dfabdb6ea7b5e0054548ed9
2020-01-02 09:56:42,980:DEBUG:140518462981888:for trip = 5dfabdb5ea7b5e0054548e55, adding start_place 5dfabdb6ea7b5e0054548ed9 and end_place 5dfabdb6ea7b5e0054548eda
2020-01-02 09:56:42,980:DEBUG:140518462981888:for trip = 5dfc0f15ea7b5e015419dfa0, adding start_place 5dfabdb6ea7b5e0054548eda and end_place 5dfc0f15ea7b5e015419dfca
2020-01-02 09:56:42,981:DEBUG:140518462981888:place id 5dfc0f15ea7b5e015419dfca is not in the map, searching in database
2020-01-02 09:56:42,982:DEBUG:140518462981888:retrieved object Entry({'_id': ObjectId('5dfc0f15ea7b5e015419dfca'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/cleaned_place', 'platform': 'server', 'write_ts': 1576800021.9684024, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 19, 'hour': 16, 'minute': 0, 'second': 21, 'weekday': 3, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-19T16:00:21.968402-08:00'}, 'data': {'source': 'DwellSegmentationDistFilter', 'enter_ts': 1576728001.132341, 'enter_local_dt': {'year': 2019, 'month': 12, 'day': 19, 'hour': 15, 'minute': 0, 'second': 1, 'weekday': 3, 'timezone': 'Australia/Sydney'}, 'enter_fmt_time': '2019-12-19T15:00:01.132341+11:00', 'location': {'type': 'Point', 'coordinates': [151.23464050939018, -33.91742855139933]}, 'raw_places': [ObjectId('5dfc0f14ea7b5e015419df94'), ObjectId('5dfc0f14ea7b5e015419df94')], 'ending_trip': ObjectId('5dfc0f15ea7b5e015419dfa0'), 'starting_trip': ObjectId('5dfc0f15ea7b5e015419dfa1'), 'exit_ts': 1576728001.132341, 'exit_fmt_time': '2019-12-19T15:00:01.132341+11:00', 'exit_local_dt': {'year': 2019, 'month': 12, 'day': 19, 'hour': 15, 'minute': 0, 'second': 1, 'weekday': 3, 'timezone': 'Australia/Sydney'}, 'duration': 0.0}}) and added to id_map
2020-01-02 09:56:42,982:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5df031a9ea7b5e470afa4b85'), 'metadata.key': 'analysis/cleaned_stop'} with sort_key data.enter_ts
2020-01-02 09:56:43,008:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5df031a9ea7b5e470afa4b85'), 'metadata.key': 'analysis/cleaned_section'} with sort_key data.start_ts
2020-01-02 09:56:43,042:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 0, len(trips) = 1
2020-01-02 09:56:43,042:DEBUG:140518462981888:places_or_stops = [] 
2020-01-02 09:56:43,042:DEBUG:140518462981888:trips_or_sections = [ObjectId('5df031a9ea7b5e470afa4b87')] 
2020-01-02 09:56:43,042:DEBUG:140518462981888:Starting with element of type trip, id 5df031a9ea7b5e470afa4b87, details Entry({'_id': ObjectId('5df031a9ea7b5e470afa4b87'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/cleaned_section', 'platform': 'server', 'write_ts': 1576022441.679734, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 0, 'second': 41, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:00:41.679734-08:00'}, 'data': {'source': 'SmoothedHighConfidenceMotion', 'trip_id': ObjectId('5df031a9ea7b5e470afa4b85'), 'start_ts': 1576013167.0459037, 'start_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 8, 'minute': 26, 'second': 7, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'start_fmt_time': '2019-12-11T08:26:07.045904+11:00', 'start_loc': {'type': 'Point', 'coordinates': [151.23716632020535, -33.916413875805034]}, 'end_ts': 1576013980.6980438, 'end_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 8, 'minute': 39, 'second': 40, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'end_fmt_time': '2019-12-11T08:39:40.698044+11:00', 'end_loc': {'type': 'Point', 'coordinates': [151.23954535866795, -33.9155451382473]}, 'duration': 813.6521401405334, 'speeds': [0.0, 1.0457873051379272, 1.0457865023841617, 1.0457856997136996, 1.0457848968723964, 1.0457840941143968, 1.0457832913549854, 0.9498685686299752, 0.8317697800167253, 0.8317690211709302, 0.8712464535531071, 1.372655819370826, 1.6182387448709008, 2.0956942096378435, 0.16762012306963542, 0.1343130049114528, 1.0047922166009668, 0.5586010830975046, 1.0867738834217493, 1.0867748532240142, 1.0867758230657247, 1.086776792881386, 1.0867777626709987, 1.0867787325000566, 1.0867797023030654, 1.0867806720800253, 1.08678164189643, 1.0867826117356834, 1.086783155375257], 'distances': [0.0, 31.373619154137817, 31.37359507152485, 31.373570991410986, 31.373546906171892, 31.3735228234319, 31.37349874064956, 28.496057058899254, 24.95309340050176, 24.953070635127908, 26.137393606593214, 41.17967458112478, 48.547162346127024, 62.8708262891353, 5.028603692089063, 4.029390147343584, 30.143766498029006, 16.758032492925135, 32.60321650265248, 32.60324559672043, 32.60327469197174, 32.60330378644158, 32.60333288012996, 32.6033619750017, 32.60339106909196, 32.60342016240076, 32.6034492568929, 32.6034783520705, 3.969084385801574], 'distance': 831.3409830943984, 'sensed_mode': 0}})
2020-01-02 09:56:43,044:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576013980.6980438, '$gte': 1576013167.0459037}}, sort_key = data.ts
2020-01-02 09:56:43,044:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:43,044:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:43,045:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 29
2020-01-02 09:56:43,047:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 29
2020-01-02 09:56:43,051:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5df031a9ea7b5e470afa4b88'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576022441.6816823, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 0, 'second': 41, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:00:41.681682-08:00'}, 'data': {'altitude': 59.053955078125, 'fmt_time': '2019-12-11T08:26:07.045904+11:00', 'latitude': -33.916413875805034, 'loc': {'type': 'Point', 'coordinates': [151.23716632020535, -33.916413875805034]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 8, 'minute': 26, 'second': 7, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 151.23716632020535, 'ts': 1576013167.0459037, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 0, 'section': ObjectId('5df031a9ea7b5e470afa4b87')}})
2020-01-02 09:56:43,055:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5df031a9ea7b5e470afa4b87')}
2020-01-02 09:56:43,089:DEBUG:140518462981888:mapped cleaned section 5df031a9ea7b5e470afa4b87 -> inferred section 5df031bdea7b5e470afa4bd7
2020-01-02 09:56:43,089:DEBUG:140518462981888:changing mode from MotionTypes.IN_VEHICLE -> PredictedModeTypes.CAR
2020-01-02 09:56:43,091:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576013980.6980438, '$gte': 1576013167.0459037}}, sort_key = data.ts
2020-01-02 09:56:43,091:DEBUG:140518462981888:orig_ts_db_keys = ['manual/incident'], analysis_ts_db_keys = []
2020-01-02 09:56:43,092:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:43,093:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:43,094:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 0
2020-01-02 09:56:43,819:DEBUG:140518462981888:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576013980.6980438, '$gte': 1576013167.0459037}}
2020-01-02 09:56:43,821:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5df031a9ea7b5e470afa4ba5'), 'metadata.key': 'analysis/cleaned_stop'} with sort_key data.enter_ts
2020-01-02 09:56:43,845:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5df031a9ea7b5e470afa4ba5'), 'metadata.key': 'analysis/cleaned_section'} with sort_key data.start_ts
2020-01-02 09:56:43,877:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 1, len(trips) = 2
2020-01-02 09:56:43,877:DEBUG:140518462981888:places_or_stops = [ObjectId('5df031aaea7b5e470afa4bc6')] 
2020-01-02 09:56:43,877:DEBUG:140518462981888:trips_or_sections = [ObjectId('5df031a9ea7b5e470afa4ba7'), ObjectId('5df031aaea7b5e470afa4bbb')] 
2020-01-02 09:56:43,877:DEBUG:140518462981888:to find start, comparing place 5df031aaea7b5e470afa4bc6 with trip 5df031a9ea7b5e470afa4ba7
2020-01-02 09:56:43,878:DEBUG:140518462981888:Starting with element of type trip, id 5df031a9ea7b5e470afa4ba7, details Entry({'_id': ObjectId('5df031a9ea7b5e470afa4ba7'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/cleaned_section', 'platform': 'server', 'write_ts': 1576022441.9208112, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 0, 'second': 41, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:00:41.920811-08:00'}, 'data': {'source': 'SmoothedHighConfidenceMotion', 'trip_id': ObjectId('5df031a9ea7b5e470afa4ba5'), 'start_ts': 1576015317.246713, 'start_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 9, 'minute': 1, 'second': 57, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'start_fmt_time': '2019-12-11T09:01:57.246713+11:00', 'start_loc': {'type': 'Point', 'coordinates': [151.23954535866795, -33.9155451382473]}, 'end_ts': 1576015850.257951, 'end_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 9, 'minute': 10, 'second': 50, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'end_fmt_time': '2019-12-11T09:10:50.257951+11:00', 'end_loc': {'type': 'Point', 'coordinates': [151.23047276882448, -33.93451822831184]}, 'duration': 533.0112380981445, 'speeds': [0.0, 6.516311522972702, 3.8504802058707246, 2.466682857210349, 12.909551052732281, 2.539675023534426, 9.134462150615212, 5.774833597366944, 5.094062983901709, 4.471576697861121, 3.6732220820288806, 4.684385830908656, 7.031999652516222, 13.664304877630148, 5.249129744519148, 0.6849354624532297, 2.1476576333054256, 0.5998438322378036, 1.1693533966035479], 'distances': [0.0, 195.48934568918108, 115.51440617612174, 74.00048571631046, 387.28653158196846, 76.19025070603277, 274.03386451845637, 173.2450079210083, 152.82188951705126, 134.1473009358336, 110.19666246086642, 140.5315749272597, 210.95998957548667, 409.92914632890444, 157.47389233557442, 20.54806387359689, 64.42972899916276, 17.995314967134107, 26.908269430118274], 'distance': 2741.7017256600675, 'sensed_mode': 7, 'end_stop': ObjectId('5df031aaea7b5e470afa4bc6')}})
2020-01-02 09:56:43,879:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576015850.257951, '$gte': 1576015317.246713}}, sort_key = data.ts
2020-01-02 09:56:43,879:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:43,880:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:43,881:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 19
2020-01-02 09:56:43,882:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 19
2020-01-02 09:56:43,885:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5df031a9ea7b5e470afa4ba8'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576022441.9225798, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 0, 'second': 41, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:00:41.922580-08:00'}, 'data': {'altitude': 68.95358276367188, 'fmt_time': '2019-12-11T09:01:57.246713+11:00', 'latitude': -33.9155451382473, 'loc': {'type': 'Point', 'coordinates': [151.23954535866795, -33.9155451382473]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 9, 'minute': 1, 'second': 57, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 151.23954535866795, 'ts': 1576015317.246713, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 7, 'section': ObjectId('5df031a9ea7b5e470afa4ba7')}})
2020-01-02 09:56:43,888:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5df031a9ea7b5e470afa4ba7')}
2020-01-02 09:56:43,919:DEBUG:140518462981888:mapped cleaned section 5df031a9ea7b5e470afa4ba7 -> inferred section 5df031bdea7b5e470afa4bd9
2020-01-02 09:56:43,920:DEBUG:140518462981888:changing mode from MotionTypes.WALKING -> PredictedModeTypes.BICYCLING
2020-01-02 09:56:43,921:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576016111.4118319, '$gte': 1576015868.337081}}, sort_key = data.ts
2020-01-02 09:56:43,921:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:43,922:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:43,923:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 10
2020-01-02 09:56:43,924:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 10
2020-01-02 09:56:43,926:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5df031aaea7b5e470afa4bbc'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576022442.0075042, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 0, 'second': 42, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:00:42.007504-08:00'}, 'data': {'altitude': 31.86054039001465, 'fmt_time': '2019-12-11T09:11:08.337081+11:00', 'latitude': -33.934555384362056, 'loc': {'type': 'Point', 'coordinates': [151.23045385829286, -33.934555384362056]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 9, 'minute': 11, 'second': 8, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 151.23045385829286, 'ts': 1576015868.337081, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 0, 'section': ObjectId('5df031aaea7b5e470afa4bbb')}})
2020-01-02 09:56:43,928:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5df031aaea7b5e470afa4bbb')}
2020-01-02 09:56:43,959:DEBUG:140518462981888:mapped cleaned section 5df031aaea7b5e470afa4bbb -> inferred section 5df031bdea7b5e470afa4bdb
2020-01-02 09:56:43,959:DEBUG:140518462981888:changing mode from MotionTypes.IN_VEHICLE -> PredictedModeTypes.BUS
2020-01-02 09:56:43,961:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576016111.4118319, '$gte': 1576015317.246713}}, sort_key = data.ts
2020-01-02 09:56:43,961:DEBUG:140518462981888:orig_ts_db_keys = ['manual/incident'], analysis_ts_db_keys = []
2020-01-02 09:56:43,962:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:43,963:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:43,964:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 0
2020-01-02 09:56:44,690:DEBUG:140518462981888:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576016111.4118319, '$gte': 1576015317.246713}}
2020-01-02 09:56:44,691:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5df03438ea7b5e4729725aa3'), 'metadata.key': 'analysis/cleaned_stop'} with sort_key data.enter_ts
2020-01-02 09:56:44,718:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5df03438ea7b5e4729725aa3'), 'metadata.key': 'analysis/cleaned_section'} with sort_key data.start_ts
2020-01-02 09:56:44,751:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 2, len(trips) = 3
2020-01-02 09:56:44,751:DEBUG:140518462981888:places_or_stops = [ObjectId('5df03439ea7b5e4729725b7a'), ObjectId('5df03439ea7b5e4729725b7b')] 
2020-01-02 09:56:44,752:DEBUG:140518462981888:trips_or_sections = [ObjectId('5df03439ea7b5e4729725aa5'), ObjectId('5df03439ea7b5e4729725b1e'), ObjectId('5df03439ea7b5e4729725b42')] 
2020-01-02 09:56:44,752:DEBUG:140518462981888:to find start, comparing place 5df03439ea7b5e4729725b7a with trip 5df03439ea7b5e4729725aa5
2020-01-02 09:56:44,752:DEBUG:140518462981888:Starting with element of type trip, id 5df03439ea7b5e4729725aa5, details Entry({'_id': ObjectId('5df03439ea7b5e4729725aa5'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/cleaned_section', 'platform': 'server', 'write_ts': 1576023097.4795623, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 11, 'second': 37, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:11:37.479562-08:00'}, 'data': {'source': 'SmoothedHighConfidenceMotion', 'trip_id': ObjectId('5df03438ea7b5e4729725aa3'), 'start_ts': 1576016183.5450575, 'start_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 9, 'minute': 16, 'second': 23, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'start_fmt_time': '2019-12-11T09:16:23.545058+11:00', 'start_loc': {'type': 'Point', 'coordinates': [151.2286641978205, -33.939533789701116]}, 'end_ts': 1576019736.369357, 'end_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 10, 'minute': 15, 'second': 36, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'end_fmt_time': '2019-12-11T10:15:36.369357+11:00', 'end_loc': {'type': 'Point', 'coordinates': [150.98015686197525, -34.219249202640995]}, 'duration': 3552.8242995738983, 'speeds': [0.0, 12.72864966196136, 8.108757566111448, 10.26325378591943, 11.103298035184936, 2.24846860332449, 1.1245103207266667, 16.32379871740363, 17.279549635676382, 17.89786887886859, 14.97303539255542, 9.54368655037, 6.509087324158102, 0.7792573700903589, 0.7792573694675708, 14.899042923231223, 12.832233822218466, 15.362274281334093, 15.485810104071472, 15.230962734533657, 16.506859828899408, 18.260011916381266, 18.240951199032466, 18.525234481137208, 17.433766236054435, 16.457727844681774, 14.275614633614332, 10.540090947892283, 5.688284525492349, 5.971429025625652, 5.491699931998487, 10.047760016871802, 7.33976179865818, 7.20926503054111, 7.772472042213962, 8.773612237159478, 9.69612801384345, 10.318868485517847, 15.636862104063615, 19.291412008858448, 20.989054052692556, 21.113522051764402, 20.255739195120455, 21.98690737277241, 26.497651655617712, 26.579410088495088, 27.495047252407428, 24.05007092343597, 12.183888117010914, 6.157833885237342, 15.582572049765899, 16.974522779424607, 10.657980245598758, 8.061347275489332, 15.612247319299476, 13.870504214881802, 21.60358318077042, 21.055286997208206, 23.339866901706518, 21.037651096556637, 20.770386229028045, 21.475814113641768, 22.568523317938112, 22.231194704385565, 22.17606031464682, 12.319512067005977, 0.9036342086057126, 1.618389354332784, 13.185256251379025, 18.180033214316484, 5.594724356753997, 0.7563416513267776, 5.213480273699295, 19.901068851787095, 20.13916682619259, 16.64770433603312, 18.833853721761734, 19.544246114598106, 22.276476820026577, 20.26557159602151, 21.26809449317357, 6.758037160574152, 21.054660278960004, 18.65413571722616, 16.230973242749688, 16.059784425483016, 15.276977275483818, 15.276813089966923, 15.276648894596311, 15.276484689197508, 13.05259823179013, 9.022117438462734, 4.95116337998086, 8.691362639858026, 9.880029391822983, 15.468541464553462, 18.430094994973917, 20.571527101464326, 23.12844175283696, 23.128388210800082, 23.12833466400055, 23.128281112502965, 23.128227556330543, 23.767710323969986, 21.109157421069092, 25.171239824225882, 25.171001621906157, 25.17076339630838, 25.170525147437914, 25.170286875404265, 25.17004858002723, 28.430705996345033, 27.309309863558614, 22.78001482322354, 17.568452162391527, 11.113289852414665, 19.89238562906412, 18.513074498222966, 18.51288291023099, 18.512746159922102], 'distances': [0.0, 381.8594898588408, 243.26272698334347, 307.8976135775829, 333.0989410555481, 67.4540580997347, 33.7353096218, 489.71396152210895, 518.3864890702914, 536.9360663660577, 449.1910617766626, 286.31059651109996, 195.27261972474307, 23.377721102710765, 23.377721084027126, 446.97128769693666, 384.967014666554, 460.8682284400228, 464.57430312214416, 456.9288820360097, 495.2057948669822, 547.800357491438, 547.228535970974, 555.7570344341162, 523.012987081633, 493.73183534045324, 428.26843900842994, 316.2027284367685, 170.64853576477046, 179.14287076876957, 164.75099795995462, 301.4328005061541, 220.1928539597454, 216.27795091623332, 233.17416126641885, 263.2083671147843, 290.8838404153035, 309.5660545655354, 469.10586312190844, 578.7423602657534, 629.6716215807767, 633.4056615529321, 607.6721758536137, 659.6072211831723, 794.9295496685314, 797.3823026548527, 824.8514175722229, 721.5021277030792, 365.5166435103274, 184.73501655712028, 467.47716149297696, 509.2356833827382, 319.7394073679627, 241.84041826467998, 468.36741957898425, 416.11512644645404, 648.1074954231126, 631.6586099162462, 700.1960070511956, 631.1295328966991, 623.1115868708414, 644.274423409253, 677.0556995381434, 666.9358411315669, 665.2818094394046, 369.5853620101793, 27.10902625817138, 48.55168062998352, 395.55768754137074, 545.4009964294945, 167.8417307026199, 22.690249539803325, 156.40440821097886, 597.0320655536128, 604.1750047857777, 499.4311300809935, 565.015611652852, 586.3273834379432, 668.2943046007973, 607.9671478806453, 638.0428347952071, 202.74111481722457, 631.6398083688001, 559.6240715167849, 486.92919728249063, 481.7935327644905, 458.3093182645145, 458.3043926990077, 458.2994668378893, 458.29454067592525, 391.5779469537039, 270.663523153882, 148.53490139942582, 260.7408791957408, 296.4008817546895, 464.0562439366039, 552.9028498492175, 617.1458130439298, 693.8532525851087, 693.8516463240024, 693.8500399200166, 693.8484333750889, 693.8468266899163, 713.0313097190996, 633.2747226320728, 755.1371947267764, 755.1300486571847, 755.1229018892515, 755.1157544231374, 755.108606262128, 755.1014574008169, 852.921179890351, 819.2792959067584, 683.4004446967061, 527.0535648717458, 333.39869557244, 596.7715688719236, 555.392234946689, 555.3864873069297, 237.4130026903767], 'distance': 56142.99219760252, 'sensed_mode': 0, 'end_stop': ObjectId('5df03439ea7b5e4729725b7a')}})
2020-01-02 09:56:44,754:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576019736.369357, '$gte': 1576016183.5450575}}, sort_key = data.ts
2020-01-02 09:56:44,754:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:44,755:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:44,756:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 121
2020-01-02 09:56:44,758:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 121
2020-01-02 09:56:44,772:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5df03439ea7b5e4729725aa6'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576023097.483507, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 11, 'second': 37, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:11:37.483507-08:00'}, 'data': {'altitude': 31.4, 'fmt_time': '2019-12-11T09:16:23.545058+11:00', 'latitude': -33.939533789701116, 'loc': {'type': 'Point', 'coordinates': [151.2286641978205, -33.939533789701116]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 9, 'minute': 16, 'second': 23, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 151.2286641978205, 'ts': 1576016183.5450575, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 0, 'section': ObjectId('5df03439ea7b5e4729725aa5')}})
2020-01-02 09:56:44,788:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5df03439ea7b5e4729725aa5')}
2020-01-02 09:56:44,801:DEBUG:140518454589184:finished querying values for ['manual/mode_confirm'], count = 77
2020-01-02 09:56:44,802:DEBUG:140517975258880:finished querying values for ['manual/purpose_confirm'], count = 81
2020-01-02 09:56:44,803:DEBUG:140518454589184:finished querying values for [], count = 0
2020-01-02 09:56:44,803:DEBUG:140517975258880:finished querying values for [], count = 0
2020-01-02 09:56:44,822:DEBUG:140518462981888:mapped cleaned section 5df03439ea7b5e4729725aa5 -> inferred section 5df03442ea7b5e4729725b7f
2020-01-02 09:56:44,822:DEBUG:140518462981888:changing mode from MotionTypes.IN_VEHICLE -> PredictedModeTypes.CAR
2020-01-02 09:56:44,824:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576020726.789994, '$gte': 1576019736.369357}}, sort_key = data.ts
2020-01-02 09:56:44,825:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:44,825:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:44,826:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 36
2020-01-02 09:56:44,827:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 36
2020-01-02 09:56:44,832:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5df03439ea7b5e4729725b1f'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576023097.7289593, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 11, 'second': 37, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:11:37.728959-08:00'}, 'data': {'altitude': 253.40890502929688, 'fmt_time': '2019-12-11T10:15:36.369357+11:00', 'latitude': -34.219249202640995, 'loc': {'type': 'Point', 'coordinates': [150.98015686197525, -34.219249202640995]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 10, 'minute': 15, 'second': 36, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 150.98015686197525, 'ts': 1576019736.369357, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 1, 'section': ObjectId('5df03439ea7b5e4729725b1e')}})
2020-01-02 09:56:44,837:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5df03439ea7b5e4729725b1e')}
2020-01-02 09:56:44,861:DEBUG:140518504945408:finished querying values for ['manual/confirm_survey'], count = 1
2020-01-02 09:56:44,862:DEBUG:140518504945408:finished querying values for [], count = 0
2020-01-02 09:56:44,867:DEBUG:140518462981888:mapped cleaned section 5df03439ea7b5e4729725b1e -> inferred section 5df03442ea7b5e4729725b81
2020-01-02 09:56:44,868:DEBUG:140518462981888:changing mode from MotionTypes.BICYCLING -> PredictedModeTypes.BICYCLING
2020-01-02 09:56:44,869:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576022435.047432, '$gte': 1576020819.051337}}, sort_key = data.ts
2020-01-02 09:56:44,869:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:44,870:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:44,871:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 55
2020-01-02 09:56:44,872:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 55
2020-01-02 09:56:44,879:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5df03439ea7b5e4729725b43'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576023097.8894522, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 10, 'hour': 16, 'minute': 11, 'second': 37, 'weekday': 1, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-10T16:11:37.889452-08:00'}, 'data': {'altitude': 26.1321964263916, 'fmt_time': '2019-12-11T10:33:39.051337+11:00', 'latitude': -34.247714644329854, 'loc': {'type': 'Point', 'coordinates': [150.97632989301437, -34.247714644329854]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 10, 'minute': 33, 'second': 39, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 150.97632989301437, 'ts': 1576020819.051337, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 0, 'section': ObjectId('5df03439ea7b5e4729725b42')}})
2020-01-02 09:56:44,887:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5df03439ea7b5e4729725b42')}
2020-01-02 09:56:44,918:DEBUG:140518462981888:mapped cleaned section 5df03439ea7b5e4729725b42 -> inferred section 5df03442ea7b5e4729725b83
2020-01-02 09:56:44,919:DEBUG:140518462981888:changing mode from MotionTypes.IN_VEHICLE -> PredictedModeTypes.CAR
2020-01-02 09:56:44,921:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576022435.047432, '$gte': 1576016183.5450575}}, sort_key = data.ts
2020-01-02 09:56:44,921:DEBUG:140518462981888:orig_ts_db_keys = ['manual/incident'], analysis_ts_db_keys = []
2020-01-02 09:56:44,926:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:44,926:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:44,931:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 0
2020-01-02 09:56:45,665:DEBUG:140518462981888:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576022435.047432, '$gte': 1576016183.5450575}}
2020-01-02 09:56:45,667:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5dfabdb3ea7b5e0054548de2'), 'metadata.key': 'analysis/cleaned_stop'} with sort_key data.enter_ts
2020-01-02 09:56:45,693:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5dfabdb3ea7b5e0054548de2'), 'metadata.key': 'analysis/cleaned_section'} with sort_key data.start_ts
2020-01-02 09:56:45,726:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 1, len(trips) = 2
2020-01-02 09:56:45,726:DEBUG:140518462981888:places_or_stops = [ObjectId('5dfabdb3ea7b5e0054548e1e')] 
2020-01-02 09:56:45,726:DEBUG:140518462981888:trips_or_sections = [ObjectId('5dfabdb3ea7b5e0054548de4'), ObjectId('5dfabdb3ea7b5e0054548e1b')] 
2020-01-02 09:56:45,726:DEBUG:140518462981888:to find start, comparing place 5dfabdb3ea7b5e0054548e1e with trip 5dfabdb3ea7b5e0054548de4
2020-01-02 09:56:45,727:DEBUG:140518462981888:Starting with element of type trip, id 5dfabdb3ea7b5e0054548de4, details Entry({'_id': ObjectId('5dfabdb3ea7b5e0054548de4'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/cleaned_section', 'platform': 'server', 'write_ts': 1576713651.3790882, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 18, 'hour': 16, 'minute': 0, 'second': 51, 'weekday': 2, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-18T16:00:51.379088-08:00'}, 'data': {'source': 'SmoothedHighConfidenceMotion', 'trip_id': ObjectId('5dfabdb3ea7b5e0054548de2'), 'start_ts': 1576025754.6791606, 'start_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 11, 'minute': 55, 'second': 54, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'start_fmt_time': '2019-12-11T11:55:54.679161+11:00', 'start_loc': {'type': 'Point', 'coordinates': [150.9726934043234, -34.25623971040757]}, 'end_ts': 1576027333.671842, 'end_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 12, 'minute': 22, 'second': 13, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'end_fmt_time': '2019-12-11T12:22:13.671842+11:00', 'end_loc': {'type': 'Point', 'coordinates': [150.9018845246931, -34.30935963951987]}, 'duration': 1578.992681503296, 'speeds': [0.0, 8.019079337566394, 6.6527312977374065, 10.106304790325051, 13.571177364673584, 3.6501033085598924, 0.2927808405607807, 0.8615563662783331, 10.142200787909053, 14.045624040479426, 11.44325988256609, 12.854296355679486, 15.049798125981875, 12.049475387634548, 10.451449141621312, 11.16484869505898, 12.368890149047091, 12.374195581970481, 14.4805219393557, 13.924462562107433, 14.237964526008232, 11.635502074835616, 11.740400231655606, 13.499343487036043, 14.050555618606232, 10.641412616569237, 3.952425462041547, 5.982277648944071, 5.73883563340921, 3.326398345424613, 1.8471119462210757, 5.431157906876067, 5.568863171593365, 9.49243132614814, 7.761044319661293, 10.423471634932744, 16.044816849934975, 14.43874118591937, 14.295686981868649, 15.98150776117427, 10.355552849094153, 14.545509993056948, 11.822901549569668, 13.27214598766012, 15.818363358107037, 15.616954895880392, 20.581602804456956, 19.999928221735946, 5.739798949147526, 17.486805065270264, 19.70297821442464, 19.72877208704315, 12.927390614959883, 4.6089742357925765], 'distances': [0.0, 240.57238012699185, 199.5819389321222, 303.18914370975153, 407.1353209402075, 109.50309925679677, 8.78342521682342, 25.846690988349994, 304.2660236372716, 421.3687212143828, 343.29779647698274, 385.6288906703846, 451.49394377945623, 361.48426162903644, 313.54347424863937, 334.9454608517694, 371.0667044714127, 371.22586745911445, 434.415658180671, 417.733876863223, 427.138935780247, 349.0650622450685, 352.2120069496682, 404.9803046110813, 421.51666855818695, 319.24237849707714, 118.57276386124641, 179.4683294683221, 172.1650690022763, 99.79195036273839, 55.41335838663227, 162.93473720628202, 167.06589514780094, 284.7729397844442, 232.8313295898388, 312.7041490479823, 481.3445054980492, 433.1622355775811, 428.87060945605947, 479.4452328352281, 310.6665854728246, 436.3652997917084, 354.68704648709, 398.16437962980365, 474.5509007432111, 468.5086468764118, 617.4480841337087, 599.9978466520784, 172.1939684744258, 524.6041519581079, 591.0893464327391, 591.8631626112946, 387.8217184487965, 87.53677971730501], 'distance': 17703.27905794871, 'sensed_mode': 0, 'end_stop': ObjectId('5dfabdb3ea7b5e0054548e1e')}})
2020-01-02 09:56:45,728:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576027333.671842, '$gte': 1576025754.6791606}}, sort_key = data.ts
2020-01-02 09:56:45,728:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:45,729:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:45,730:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 54
2020-01-02 09:56:45,731:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 54
2020-01-02 09:56:45,738:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5dfabdb3ea7b5e0054548de5'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576713651.3816364, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 18, 'hour': 16, 'minute': 0, 'second': 51, 'weekday': 2, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-18T16:00:51.381636-08:00'}, 'data': {'altitude': 95.9414005279541, 'fmt_time': '2019-12-11T11:55:54.679161+11:00', 'latitude': -34.25623971040757, 'loc': {'type': 'Point', 'coordinates': [150.9726934043234, -34.25623971040757]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 11, 'minute': 55, 'second': 54, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 150.9726934043234, 'ts': 1576025754.6791606, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 0, 'section': ObjectId('5dfabdb3ea7b5e0054548de4')}})
2020-01-02 09:56:45,746:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5dfabdb3ea7b5e0054548de4')}
2020-01-02 09:56:45,779:DEBUG:140518462981888:mapped cleaned section 5dfabdb3ea7b5e0054548de4 -> inferred section 5dfabdc1ea7b5e0054548edd
2020-01-02 09:56:45,780:DEBUG:140518462981888:changing mode from MotionTypes.IN_VEHICLE -> PredictedModeTypes.CAR
2020-01-02 09:56:45,781:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576027402.674427, '$gte': 1576027396.190806}}, sort_key = data.ts
2020-01-02 09:56:45,781:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:45,782:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:45,783:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 2
2020-01-02 09:56:45,784:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 2
2020-01-02 09:56:45,785:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5dfabdb3ea7b5e0054548e1c'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576713651.5013978, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 18, 'hour': 16, 'minute': 0, 'second': 51, 'weekday': 2, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-18T16:00:51.501398-08:00'}, 'data': {'altitude': 353.56243896484375, 'fmt_time': '2019-12-11T12:23:16.190806+11:00', 'latitude': -34.30879933154692, 'loc': {'type': 'Point', 'coordinates': [150.9025607631839, -34.30879933154692]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 12, 'minute': 23, 'second': 16, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 150.9025607631839, 'ts': 1576027396.190806, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 7, 'section': ObjectId('5dfabdb3ea7b5e0054548e1b')}})
2020-01-02 09:56:45,786:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5dfabdb3ea7b5e0054548e1b')}
2020-01-02 09:56:45,818:DEBUG:140518462981888:mapped cleaned section 5dfabdb3ea7b5e0054548e1b -> inferred section 5dfabdc1ea7b5e0054548edf
2020-01-02 09:56:45,818:DEBUG:140518462981888:changing mode from MotionTypes.WALKING -> PredictedModeTypes.WALKING
2020-01-02 09:56:45,820:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576027402.674427, '$gte': 1576025754.6791606}}, sort_key = data.ts
2020-01-02 09:56:45,820:DEBUG:140518462981888:orig_ts_db_keys = ['manual/incident'], analysis_ts_db_keys = []
2020-01-02 09:56:45,822:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:45,823:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:45,825:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 0
2020-01-02 09:56:46,611:DEBUG:140518462981888:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576027402.674427, '$gte': 1576025754.6791606}}
2020-01-02 09:56:46,612:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5dfabdb4ea7b5e0054548e1f'), 'metadata.key': 'analysis/cleaned_stop'} with sort_key data.enter_ts
2020-01-02 09:56:46,636:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5dfabdb4ea7b5e0054548e1f'), 'metadata.key': 'analysis/cleaned_section'} with sort_key data.start_ts
2020-01-02 09:56:46,657:DEBUG:140518454589184:orig_ts_db_matches = 77, analysis_ts_db_matches = 0
2020-01-02 09:56:46,661:DEBUG:140517975258880:orig_ts_db_matches = 81, analysis_ts_db_matches = 0
2020-01-02 09:56:46,668:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 1, len(trips) = 2
2020-01-02 09:56:46,668:DEBUG:140518462981888:places_or_stops = [ObjectId('5dfabdb4ea7b5e0054548e54')] 
2020-01-02 09:56:46,668:DEBUG:140518462981888:trips_or_sections = [ObjectId('5dfabdb4ea7b5e0054548e21'), ObjectId('5dfabdb4ea7b5e0054548e4a')] 
2020-01-02 09:56:46,668:DEBUG:140518462981888:to find start, comparing place 5dfabdb4ea7b5e0054548e54 with trip 5dfabdb4ea7b5e0054548e21
2020-01-02 09:56:46,669:DEBUG:140518462981888:Starting with element of type trip, id 5dfabdb4ea7b5e0054548e21, details Entry({'_id': ObjectId('5dfabdb4ea7b5e0054548e21'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/cleaned_section', 'platform': 'server', 'write_ts': 1576713652.8175032, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 18, 'hour': 16, 'minute': 0, 'second': 52, 'weekday': 2, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-18T16:00:52.817503-08:00'}, 'data': {'source': 'SmoothedHighConfidenceMotion', 'trip_id': ObjectId('5dfabdb4ea7b5e0054548e1f'), 'start_ts': 1576030197.0164506, 'start_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 13, 'minute': 9, 'second': 57, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'start_fmt_time': '2019-12-11T13:09:57.016451+11:00', 'start_loc': {'type': 'Point', 'coordinates': [150.90250463172157, -34.3088898762662]}, 'end_ts': 1576031348.399823, 'end_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 13, 'minute': 29, 'second': 8, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'end_fmt_time': '2019-12-11T13:29:08.399823+11:00', 'end_loc': {'type': 'Point', 'coordinates': [150.9052249787575, -34.423800048011856]}, 'duration': 1151.3833723068237, 'speeds': [0.0, 18.86510217297189, 19.949265810955385, 22.30020474350783, 21.712777714856806, 24.9144567311157, 26.236630803753656, 24.001853093410578, 20.991526750805452, 24.78880879297478, 24.944672866200396, 18.58791083607255, 27.649167209374404, 26.414848748242665, 21.221919069703027, 22.589966015277874, 23.543625978372027, 21.097818493200325, 20.424510915101916, 18.697789904707594, 17.999555365508364, 19.072243468427757, 16.758197350632297, 11.601379324910912, 3.2975194128540704, 8.369127530458728, 5.165812333620325, 1.3427467459025912, 9.83267382482211, 8.162315220152927, 9.653774498020002, 11.933490786657142, 5.648839267360788, 1.1457091736484535, 12.042336851923327, 5.589928765102359, 10.583176793998529, 4.265576392335038, 4.525009975647771, 7.445834656127039], 'distances': [0.0, 565.9530651891567, 598.4779743286615, 669.0061423052349, 651.3833314457041, 747.433701933471, 787.0989241126097, 720.0555928023173, 629.7458025241635, 743.6642637892434, 748.3401859860119, 557.6373250821765, 829.4750162812321, 792.44546244728, 636.6575720910909, 677.6989804583362, 706.3087793511609, 632.9345547960097, 612.7353274530575, 560.9336971412279, 539.986660965251, 572.1673040528327, 502.7459205189689, 348.04137974732737, 98.9255823856221, 251.07382591376185, 154.97437000860975, 40.28240237707774, 294.98021474466333, 244.8694566045878, 289.6132349406001, 358.0047235997143, 169.46517802082366, 34.37127520945361, 361.2701055576998, 167.69786295307077, 317.4953038199559, 127.96729177005112, 135.75029926943313, 84.75870802574494], 'distance': 17962.426800003388, 'sensed_mode': 0, 'end_stop': ObjectId('5dfabdb4ea7b5e0054548e54')}})
2020-01-02 09:56:46,670:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576031348.399823, '$gte': 1576030197.0164506}}, sort_key = data.ts
2020-01-02 09:56:46,671:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:46,671:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:46,672:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 40
2020-01-02 09:56:46,674:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 40
2020-01-02 09:56:46,679:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5dfabdb4ea7b5e0054548e22'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576713652.8197644, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 18, 'hour': 16, 'minute': 0, 'second': 52, 'weekday': 2, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-18T16:00:52.819764-08:00'}, 'data': {'altitude': 351.34979248046875, 'fmt_time': '2019-12-11T13:09:57.016451+11:00', 'latitude': -34.3088898762662, 'loc': {'type': 'Point', 'coordinates': [150.90250463172157, -34.3088898762662]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 13, 'minute': 9, 'second': 57, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 150.90250463172157, 'ts': 1576030197.0164506, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 0, 'section': ObjectId('5dfabdb4ea7b5e0054548e21')}})
2020-01-02 09:56:46,685:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5dfabdb4ea7b5e0054548e21')}
2020-01-02 09:56:46,721:DEBUG:140518504945408:orig_ts_db_matches = 1, analysis_ts_db_matches = 0
2020-01-02 09:56:46,722:DEBUG:140518462981888:mapped cleaned section 5dfabdb4ea7b5e0054548e21 -> inferred section 5dfabdc1ea7b5e0054548ee1
2020-01-02 09:56:46,722:DEBUG:140518462981888:changing mode from MotionTypes.IN_VEHICLE -> PredictedModeTypes.CAR
2020-01-02 09:56:46,724:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576031663.7375, '$gte': 1576031427.440288}}, sort_key = data.ts
2020-01-02 09:56:46,724:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:46,724:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:46,725:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 9
2020-01-02 09:56:46,726:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 9
2020-01-02 09:56:46,729:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5dfabdb4ea7b5e0054548e4b'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576713652.929999, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 18, 'hour': 16, 'minute': 0, 'second': 52, 'weekday': 2, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-18T16:00:52.929999-08:00'}, 'data': {'altitude': 10.556394577026367, 'fmt_time': '2019-12-11T13:30:27.440288+11:00', 'latitude': -34.42344043950647, 'loc': {'type': 'Point', 'coordinates': [150.90503292661583, -34.42344043950647]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 13, 'minute': 30, 'second': 27, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 150.90503292661583, 'ts': 1576031427.440288, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 7, 'section': ObjectId('5dfabdb4ea7b5e0054548e4a')}})
2020-01-02 09:56:46,730:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5dfabdb4ea7b5e0054548e4a')}
2020-01-02 09:56:46,763:DEBUG:140518462981888:mapped cleaned section 5dfabdb4ea7b5e0054548e4a -> inferred section 5dfabdc1ea7b5e0054548ee3
2020-01-02 09:56:46,764:DEBUG:140518462981888:changing mode from MotionTypes.WALKING -> PredictedModeTypes.WALKING
2020-01-02 09:56:46,765:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576031663.7375, '$gte': 1576030197.0164506}}, sort_key = data.ts
2020-01-02 09:56:46,765:DEBUG:140518462981888:orig_ts_db_keys = ['manual/incident'], analysis_ts_db_keys = []
2020-01-02 09:56:46,768:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:46,768:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:46,771:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 0
2020-01-02 09:56:47,443:DEBUG:140518454589184:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/mode_confirm'}], 'metadata.write_ts': {'$lte': 1577959001.594, '$gte': 0}}
2020-01-02 09:56:47,444:DEBUG:140517975258880:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/purpose_confirm'}], 'metadata.write_ts': {'$lte': 1577959001.594, '$gte': 0}}
2020-01-02 09:56:47,524:DEBUG:140518454589184:END POST /datastreams/find_entries/timestamp 74fc6ede-ece0-43b5-ade3-456ebe034e3f 4.7470738887786865 
2020-01-02 09:56:47,524:DEBUG:140518504945408:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/confirm_survey'}], 'metadata.write_ts': {'$lte': 1577959001.595, '$gte': 0}}
2020-01-02 09:56:47,527:DEBUG:140517975258880:END POST /datastreams/find_entries/timestamp 74fc6ede-ece0-43b5-ade3-456ebe034e3f 4.728916883468628 
2020-01-02 09:56:47,529:DEBUG:140518454589184:insert called with entry of type <class 'emission.core.wrapper.entry.Entry'>
2020-01-02 09:56:47,531:DEBUG:140517975258880:insert called with entry of type <class 'emission.core.wrapper.entry.Entry'>
2020-01-02 09:56:47,531:DEBUG:140518454589184:entry was fine, no need to fix it
2020-01-02 09:56:47,532:DEBUG:140517975258880:entry was fine, no need to fix it
2020-01-02 09:56:47,532:DEBUG:140518454589184:Inserting entry Entry({'_id': ObjectId('5e0dbe5f4d2a1c000e34ac3f'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': Metadata({'key': 'stats/server_api_time', 'platform': 'server', 'write_ts': 1577959007.5277634, 'time_zone': 'America/Los_Angeles', 'write_local_dt': LocalDate({'year': 2020, 'month': 1, 'day': 2, 'hour': 1, 'minute': 56, 'second': 47, 'weekday': 3, 'timezone': 'America/Los_Angeles'}), 'write_fmt_time': '2020-01-02T01:56:47.527763-08:00'}), 'data': {'name': 'POST_/datastreams/find_entries/timestamp', 'ts': 1577959007.5243874, 'reading': 4.7470738887786865}}) into timeseries
2020-01-02 09:56:47,533:DEBUG:140518504945408:END POST /datastreams/find_entries/timestamp 74fc6ede-ece0-43b5-ade3-456ebe034e3f 4.741745233535767 
2020-01-02 09:56:47,533:DEBUG:140517975258880:Inserting entry Entry({'_id': ObjectId('5e0dbe5f4d2a1c000e34ac40'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': Metadata({'key': 'stats/server_api_time', 'platform': 'server', 'write_ts': 1577959007.530061, 'time_zone': 'America/Los_Angeles', 'write_local_dt': LocalDate({'year': 2020, 'month': 1, 'day': 2, 'hour': 1, 'minute': 56, 'second': 47, 'weekday': 3, 'timezone': 'America/Los_Angeles'}), 'write_fmt_time': '2020-01-02T01:56:47.530061-08:00'}), 'data': {'name': 'POST_/datastreams/find_entries/timestamp', 'ts': 1577959007.5274208, 'reading': 4.728916883468628}}) into timeseries
2020-01-02 09:56:47,536:DEBUG:140518454589184:insert called with entry of type <class 'emission.core.wrapper.entry.Entry'>
2020-01-02 09:56:47,537:DEBUG:140518504945408:insert called with entry of type <class 'emission.core.wrapper.entry.Entry'>
2020-01-02 09:56:47,538:DEBUG:140518454589184:entry was fine, no need to fix it
2020-01-02 09:56:47,538:DEBUG:140518504945408:entry was fine, no need to fix it
2020-01-02 09:56:47,540:DEBUG:140518454589184:Inserting entry Entry({'_id': ObjectId('5e0dbe5f4d2a1c000e34ac42'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': Metadata({'key': 'stats/server_api_time', 'platform': 'server', 'write_ts': 1577959007.535051, 'time_zone': 'America/Los_Angeles', 'write_local_dt': LocalDate({'year': 2020, 'month': 1, 'day': 2, 'hour': 1, 'minute': 56, 'second': 47, 'weekday': 3, 'timezone': 'America/Los_Angeles'}), 'write_fmt_time': '2020-01-02T01:56:47.535051-08:00'}), 'data': {'name': 'POST_/datastreams/find_entries/timestamp_cputime', 'ts': 1577959007.5243874, 'reading': 4.746974335052073}}) into timeseries
2020-01-02 09:56:47,540:DEBUG:140517975258880:insert called with entry of type <class 'emission.core.wrapper.entry.Entry'>
2020-01-02 09:56:47,540:DEBUG:140518504945408:Inserting entry Entry({'_id': ObjectId('5e0dbe5f4d2a1c000e34ac41'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': Metadata({'key': 'stats/server_api_time', 'platform': 'server', 'write_ts': 1577959007.5346746, 'time_zone': 'America/Los_Angeles', 'write_local_dt': LocalDate({'year': 2020, 'month': 1, 'day': 2, 'hour': 1, 'minute': 56, 'second': 47, 'weekday': 3, 'timezone': 'America/Los_Angeles'}), 'write_fmt_time': '2020-01-02T01:56:47.534675-08:00'}), 'data': {'name': 'POST_/datastreams/find_entries/timestamp', 'ts': 1577959007.5333998, 'reading': 4.741745233535767}}) into timeseries
2020-01-02 09:56:47,541:DEBUG:140517975258880:entry was fine, no need to fix it
2020-01-02 09:56:47,542:DEBUG:140517975258880:Inserting entry Entry({'_id': ObjectId('5e0dbe5f4d2a1c000e34ac43'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': Metadata({'key': 'stats/server_api_time', 'platform': 'server', 'write_ts': 1577959007.5389152, 'time_zone': 'America/Los_Angeles', 'write_local_dt': LocalDate({'year': 2020, 'month': 1, 'day': 2, 'hour': 1, 'minute': 56, 'second': 47, 'weekday': 3, 'timezone': 'America/Los_Angeles'}), 'write_fmt_time': '2020-01-02T01:56:47.538915-08:00'}), 'data': {'name': 'POST_/datastreams/find_entries/timestamp_cputime', 'ts': 1577959007.5274208, 'reading': 4.728843034012243}}) into timeseries
2020-01-02 09:56:47,545:DEBUG:140518504945408:insert called with entry of type <class 'emission.core.wrapper.entry.Entry'>
2020-01-02 09:56:47,545:DEBUG:140518504945408:entry was fine, no need to fix it
2020-01-02 09:56:47,545:DEBUG:140518504945408:Inserting entry Entry({'_id': ObjectId('5e0dbe5f4d2a1c000e34ac44'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': Metadata({'key': 'stats/server_api_time', 'platform': 'server', 'write_ts': 1577959007.543447, 'time_zone': 'America/Los_Angeles', 'write_local_dt': LocalDate({'year': 2020, 'month': 1, 'day': 2, 'hour': 1, 'minute': 56, 'second': 47, 'weekday': 3, 'timezone': 'America/Los_Angeles'}), 'write_fmt_time': '2020-01-02T01:56:47.543447-08:00'}), 'data': {'name': 'POST_/datastreams/find_entries/timestamp_cputime', 'ts': 1577959007.5333998, 'reading': 4.741667215945199}}) into timeseries
2020-01-02 09:56:47,561:DEBUG:140518462981888:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576031663.7375, '$gte': 1576030197.0164506}}
2020-01-02 09:56:47,561:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5dfabdb5ea7b5e0054548e55'), 'metadata.key': 'analysis/cleaned_stop'} with sort_key data.enter_ts
2020-01-02 09:56:47,590:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5dfabdb5ea7b5e0054548e55'), 'metadata.key': 'analysis/cleaned_section'} with sort_key data.start_ts
2020-01-02 09:56:47,624:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 0, len(trips) = 1
2020-01-02 09:56:47,624:DEBUG:140518462981888:places_or_stops = [] 
2020-01-02 09:56:47,624:DEBUG:140518462981888:trips_or_sections = [ObjectId('5dfabdb5ea7b5e0054548e57')] 
2020-01-02 09:56:47,625:DEBUG:140518462981888:Starting with element of type trip, id 5dfabdb5ea7b5e0054548e57, details Entry({'_id': ObjectId('5dfabdb5ea7b5e0054548e57'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/cleaned_section', 'platform': 'server', 'write_ts': 1576713653.8137202, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 18, 'hour': 16, 'minute': 0, 'second': 53, 'weekday': 2, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-18T16:00:53.813720-08:00'}, 'data': {'source': 'SmoothedHighConfidenceMotion', 'trip_id': ObjectId('5dfabdb5ea7b5e0054548e55'), 'start_ts': 1576034935.079099, 'start_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 14, 'minute': 28, 'second': 55, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'start_fmt_time': '2019-12-11T14:28:55.079099+11:00', 'start_loc': {'type': 'Point', 'coordinates': [150.90687899764117, -34.42267505466979]}, 'end_ts': 1576038737.7425919, 'end_local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 15, 'minute': 32, 'second': 17, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'end_fmt_time': '2019-12-11T15:32:17.742592+11:00', 'end_loc': {'type': 'Point', 'coordinates': [150.86233683333333, -34.672025500000004]}, 'duration': 3802.6634929180145, 'speeds': [0.0, 7.697701970266743, 0.5407619480195467, 0.540762309978194, 0.5407626717619913, 1.103429559672353, 1.1546294143122036, 0.7670470890803319, 1.2520533053844882, 4.349590767910519, 4.941732894284367, 4.932544781012648, 6.45501606646713, 6.04662630790581, 14.04598986546868, 16.698003444596818, 11.25566140647641, 19.093239970916354, 19.914557958825664, 18.70138037398427, 10.203316662091874, 14.788863931604242, 20.42824117857419, 18.119713603366158, 21.35704132640657, 24.386824907130276, 24.840876588913194, 24.248533243704095, 24.847034739082922, 25.72024177822136, 24.112753050347237, 24.54732070603808, 24.18181507882618, 25.318009739079788, 24.948314261511594, 25.58299135539209, 25.80160878231712, 24.896545798502963, 24.253571817472444, 22.507892942484613, 20.91715097856014, 17.9431777317255, 19.30903993427502, 20.712432810860076, 10.31043941713771, 0.6028757792137028, 0.6028756146900354, 1.31556530001305, 12.926817967974225, 12.561647274247957, 17.67744367694892, 15.822328440720604, 16.890160399154986, 16.086087756439, 19.06261670173198, 5.9841281268085345, 3.6541915916046372, 17.51035110972388, 22.651603805573938, 22.85783688765571, 26.432160889202454, 22.50543394097945, 25.06135003562097, 26.63289625368964, 24.735956401372935, 24.296030045982874, 23.80404748777998, 25.29612859221088, 24.777421846481438, 24.465783085165747, 23.22527574885641, 21.4910999079108, 25.550015616429654, 23.586800269253715, 23.170740760023406, 13.236297722494252, 8.48442103568276, 12.45364174975862, 5.64880904522836, 1.5386594658178272, 1.1560849213206397, 2.8888576917248248, 4.563884330738464, 6.927818998125591, 7.669783734438172, 8.360585848119658, 2.34496790199444, 0.0045673724465806476, 0.00456737244271396, 0.004567372438847272, 0.004567372434980585, 0.004567372431113896, 0.004567372427247209, 0.004567372423380522, 0.004567372398531404, 0.004567372415647145, 0.004567372411780457, 0.004567372382361547, 0.0045673724040470815, 0.004567372400180392, 0.004567372396313704, 0.004567372392447017, 0.004567372388580327, 0.004567372384713639, 0.00456737238084695, 0.004567372376980262, 0.004567372373113573, 0.004567372369246885, 0.004567372365380197, 0.004567372340531087, 0.004567372357646818, 0.004567372353780129, 0.004567372349913441, 0.004567372346046751, 0.004567372342180062, 0.004567372338313373, 0.004567372334446683, 0.004567372330579993, 0.004567372326713305, 0.004567372322846615, 0.004567372318979926, 0.004567372315113236, 0.004567372311246546, 0.004567372307379857, 0.004567372303513167, 0.004567372278664066, 0.004567372295779787, 0.004567372285291456], 'distances': [0.0, 230.93105910800227, 16.2228584405864, 16.22286929934582, 16.22288015285974, 33.10288679017059, 34.638882429366106, 23.011412672409957, 37.561599161534645, 130.4877230373156, 148.251986828531, 147.97634343037944, 193.65048199401392, 181.3987892371743, 421.37969596406043, 500.9401033379046, 337.6698421942923, 572.7971991274907, 597.43673876477, 561.0414112195282, 306.0994998627562, 443.66591794812723, 612.8472353572257, 543.5914081009847, 640.7112397921971, 731.6047472139082, 745.2262976673958, 727.4559973111228, 745.4110421724877, 771.6072533466408, 723.3825915104171, 736.4196211811424, 725.4544523647854, 759.5402921723936, 748.4494278453478, 767.4897406617627, 774.0482634695136, 746.8963739550888, 727.6071545241733, 675.2367882745384, 627.5145293568042, 538.295331951765, 579.2711980282506, 621.3729843258022, 309.3131825141313, 18.086273376411086, 18.086268440701062, 39.466959000391505, 387.80453903922677, 376.8494182274387, 530.3233103084675, 474.6698532216181, 506.7048119746496, 482.58263269316996, 571.8785010519593, 179.52384380425605, 109.62574774813912, 525.3105332917164, 679.5481141672182, 685.7351066296713, 792.9648266760736, 675.1630182293835, 751.840501068629, 798.9868876106892, 742.078692041188, 728.8809013794862, 714.1214246333993, 758.8838577663264, 743.3226553944431, 733.9734925549724, 696.7582724656924, 644.7329972373241, 766.5004684928896, 707.6040080776114, 695.1222228007022, 397.08893167482756, 254.53263107048275, 373.6092524927586, 169.4642713568508, 46.15978397453482, 34.68254763961919, 86.66573075174475, 136.91652992215393, 207.83456994376775, 230.09351203314517, 250.81757544358973, 70.34903705983321, 0.13702117339741943, 0.1370211732814188, 0.13702117316541815, 0.13702117304941755, 0.1370211729334169, 0.13702117281741627, 0.13702117270141564, 0.13702117195594213, 0.13702117246941437, 0.1370211723534137, 0.13702117147084641, 0.13702117212141243, 0.13702117200541178, 0.13702117188941113, 0.1370211717734105, 0.13702117165740982, 0.13702117154140916, 0.1370211714254085, 0.13702117130940786, 0.1370211711934072, 0.13702117107740655, 0.1370211709614059, 0.1370211702159326, 0.13702117072940453, 0.13702117061340388, 0.13702117049740323, 0.13702117038140255, 0.13702117026540186, 0.13702117014940118, 0.1370211700334005, 0.1370211699173998, 0.13702116980139914, 0.13702116968539846, 0.13702116956939778, 0.13702116945339707, 0.1370211693373964, 0.1370211692213957, 0.137021169105395, 0.13702116835992198, 0.1370211688733936, 0.10351260944163874], 'distance': 39330.386206317846, 'sensed_mode': 0}})
2020-01-02 09:56:47,625:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'analysis/recreated_location'}], 'data.ts': {'$lte': 1576038737.7425919, '$gte': 1576034935.079099}}, sort_key = data.ts
2020-01-02 09:56:47,626:DEBUG:140518462981888:orig_ts_db_keys = [], analysis_ts_db_keys = ['analysis/recreated_location']
2020-01-02 09:56:47,626:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:47,627:DEBUG:140518462981888:finished querying values for ['analysis/recreated_location'], count = 128
2020-01-02 09:56:47,629:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 128
2020-01-02 09:56:47,644:DEBUG:140518462981888:first element in section_location_array = Entry({'_id': ObjectId('5dfabdb5ea7b5e0054548e58'), 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'metadata': {'key': 'analysis/recreated_location', 'platform': 'server', 'write_ts': 1576713653.8177104, 'time_zone': 'America/Los_Angeles', 'write_local_dt': {'year': 2019, 'month': 12, 'day': 18, 'hour': 16, 'minute': 0, 'second': 53, 'weekday': 2, 'timezone': 'America/Los_Angeles'}, 'write_fmt_time': '2019-12-18T16:00:53.817710-08:00'}, 'data': {'altitude': 11.264963150024414, 'fmt_time': '2019-12-11T14:28:55.079099+11:00', 'latitude': -34.42267505466979, 'loc': {'type': 'Point', 'coordinates': [150.90687899764117, -34.42267505466979]}, 'local_dt': {'year': 2019, 'month': 12, 'day': 11, 'hour': 14, 'minute': 28, 'second': 55, 'weekday': 2, 'timezone': 'Australia/Sydney'}, 'longitude': 150.90687899764117, 'ts': 1576034935.079099, 'distance': 0.0, 'speed': 0.0, 'heading': 0.0, 'idx': 0, 'mode': 0, 'section': ObjectId('5dfabdb5ea7b5e0054548e57')}})
2020-01-02 09:56:47,661:DEBUG:140518462981888:About to query {'metadata.key': 'analysis/inferred_section', 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.cleaned_section': ObjectId('5dfabdb5ea7b5e0054548e57')}
2020-01-02 09:56:47,696:DEBUG:140518462981888:mapped cleaned section 5dfabdb5ea7b5e0054548e57 -> inferred section 5dfabdc1ea7b5e0054548ee5
2020-01-02 09:56:47,696:DEBUG:140518462981888:changing mode from MotionTypes.IN_VEHICLE -> PredictedModeTypes.CAR
2020-01-02 09:56:47,698:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576038737.7425919, '$gte': 1576034935.079099}}, sort_key = data.ts
2020-01-02 09:56:47,698:DEBUG:140518462981888:orig_ts_db_keys = ['manual/incident'], analysis_ts_db_keys = []
2020-01-02 09:56:47,703:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:47,703:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:47,708:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 0
2020-01-02 09:56:48,350:DEBUG:140518462981888:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576038737.7425919, '$gte': 1576034935.079099}}
2020-01-02 09:56:48,351:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5dfc0f15ea7b5e015419dfa0'), 'metadata.key': 'analysis/cleaned_stop'} with sort_key data.enter_ts
2020-01-02 09:56:48,380:DEBUG:140518462981888:About to execute query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), 'data.trip_id': ObjectId('5dfc0f15ea7b5e015419dfa0'), 'metadata.key': 'analysis/cleaned_section'} with sort_key data.start_ts
2020-01-02 09:56:48,412:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 0, len(trips) = 0
2020-01-02 09:56:48,412:DEBUG:140518462981888:places_or_stops = [] 
2020-01-02 09:56:48,412:DEBUG:140518462981888:trips_or_sections = [] 
2020-01-02 09:56:48,413:DEBUG:140518462981888:Starting with element of type none, id None, details None
2020-01-02 09:56:48,414:DEBUG:140518462981888:curr_query = {'invalid': {'$exists': False}, 'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576728001.132341, '$gte': 1576038742.7425919}}, sort_key = data.ts
2020-01-02 09:56:48,414:DEBUG:140518462981888:orig_ts_db_keys = ['manual/incident'], analysis_ts_db_keys = []
2020-01-02 09:56:48,455:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:48,456:DEBUG:140518462981888:finished querying values for [], count = 0
2020-01-02 09:56:48,498:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 0
2020-01-02 09:56:49,191:DEBUG:140518462981888:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576728001.132341, '$gte': 1576038742.7425919}}
2020-01-02 09:56:49,192:DEBUG:140518462981888:trip count = 7, geojson count = 6
2020-01-02 09:56:49,192:DEBUG:140518462981888:type(ret_geojson) = <class 'list'>
2020-01-02 09:56:49,192:DEBUG:140518462981888:type(ret_dict) = <class 'dict'>
2020-01-02 09:56:49,230:DEBUG:140518462981888:END POST /timeline/getTrips/2019-12-11 74fc6ede-ece0-43b5-ade3-456ebe034e3f 6.481703042984009
asiripanich commented 4 years ago

@shankari did it take this long (~ 8-10s) when you deployed your own study?

shankari commented 4 years ago

@asiripanich none of the previous studies except FabMob has formally measured the response time, only checked that it "felt reasonable". Note that most studies use their own servers, which also makes it hard to compare the results since the underlying hardware is different.

wrt FabMob, it looks like the loading time is between 5 and 8 seconds (https://github.com/e-mission/e-mission-docs/issues/226#issuecomment-530925560).

I will look at your logs in greater detail today.

shankari commented 4 years ago

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).

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.

The particular day that you were retrieving had 7 trips with 11 sections.

2020-01-02 09:56:42,890:DEBUG:140518462981888:finished querying values for ['analysis/cleaned_trip', 'analysis/cleaned_untracked'], count = 7
...
$ grep "mapped cleaned section" /tmp/webserver_log_gettrips | wc -l
      11

A simpler day with fewer trips (e.g. unimodal commute to/from work) should be much faster.

@asiripanich @atton16 In parallel with this investigation, can you try with a simpler day and confirm that the load time is much faster?

shankari commented 4 years ago

Details of the operation

Operation starts:

2020-01-02 09:56:42,749:DEBUG:140518462981888:START POST /timeline/getTrips/2019-12-11

Initial place/trip query complete

2020-01-02 09:56:42,881:DEBUG:140518462981888:finished querying values for ['analysis/cleaned_place'], count = 6
2020-01-02 09:56:42,890:DEBUG:140518462981888:finished querying values for ['analysis/cleaned_trip', 'analysis/cleaned_untracked'], count = 7

Fill in the end place from the next day

2020-01-02 09:56:42,981:DEBUG:140518462981888:place id 5dfc0f15ea7b5e015419dfca is not in the map, searching in database

At this point, we have spent ~ 300 ms and already have the trip/place timeline filled in.

We then iterate through all the trips, find the sections and the related location entries.

This takes another ~ 5.5 seconds.

2020-01-02 09:56:43,042:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 0, len(trips) = 1
2020-01-02 09:56:43,092:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:43,877:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 1, len(trips) = 2
2020-01-02 09:56:43,962:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:44,751:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 2, len(trips) = 3
2020-01-02 09:56:44,926:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:45,726:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 1, len(trips) = 2
2020-01-02 09:56:45,822:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:46,668:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 1, len(trips) = 2
2020-01-02 09:56:46,768:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:47,624:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 0, len(trips) = 1
2020-01-02 09:56:47,703:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
2020-01-02 09:56:48,412:DEBUG:140518462981888:keys = (analysis/cleaned_stop, analysis/cleaned_section), len(places) = 0, len(trips) = 0
2020-01-02 09:56:48,455:DEBUG:140518462981888:finished querying values for ['manual/incident'], count = 0
shankari commented 4 years ago

I think I have a smallish fix that should cut this response time in half. Details below. I will also attach a patch for you to try out. If it works, please submit a PR to master.

While looking at the details above, I noticed that there were ~ 500 ms gaps between the time we finished processing one trip and started processing the other. Looking more carefully at those gaps, they are between these two consecutive log messages.

2020-01-02 09:56:44,931:DEBUG:140518462981888:orig_ts_db_matches = 0, analysis_ts_db_matches = 0
2020-01-02 09:56:45,665:DEBUG:140518462981888:Found 0 messages in response to query {'user_id': UUID('74fc6ede-ece0-43b5-ade3-456ebe034e3f'), '$or': [{'metadata.key': 'manual/incident'}], 'data.ts': {'$lte': 1576022435.047432, '$gte': 1576016183.5450575}}

The first message is from the timeseries: https://github.com/e-mission/e-mission-server/blob/be197e6b51573980834b00d285b536bc95e4b8a7/emission/storage/timeseries/builtin_timeseries.py#L204 the second is from the usercache: https://github.com/e-mission/e-mission-server/blob/3a5e2c921f41ea1bbeaec0d49f4fc722d418794d/emission/net/usercache/builtin_usercache.py#L136

That makes it pretty clear what is going on. We read the timeseries and the usercache and combine them. https://github.com/e-mission/e-mission-server/blob/8747e2279393f05f86e6be58f94de77909a4d455/emission/analysis/plotting/geojson/geojson_feature_converter.py#L187

BUT the usercache does not index the data.ts field, so the query data.ts': {'$lte': 1576022435.047432, '$gte': 1576016183.5450575} is super slow.

shankari commented 4 years ago

There are two possible fixes to this problem:

  1. Remove the incident retrieval as part of the geojson conversion since incident reporting is no longer enabled by default, OR
  2. Index the usercache on the data.ts field as well.

I'm attaching patches for both solutions so that you can test them out. I suspect that (1) will be the better overall solution since the incident handling is not being actively used any more. But if that leads to testing errors, then (2) will be a perfectly adequate solution as well.

shankari commented 4 years ago

I also briefly looked at the /datastreams/find_entries/<time_type> call to see whether the same issues applied there. If they did, then (2) would have been the clearly better choice. However, it turns out that the call only supports retrieval by metadata.write_ts, which is indexed in both collections.

We may want to extend this to support data queries as well, to make the mode and purpose retrieval more performant on the phone. In that case (2) is the better long-term solution.

shankari commented 4 years ago

I have attached patches for the two solutions outlined above (https://github.com/e-mission/e-mission-docs/issues/488#issuecomment-571909761)

  1. disable_incidents.patch.gz
  2. add_index.patch.gz

Please test them out and submit a PR with the fix to master.

shankari commented 4 years ago

@asiripanich @atton16 did either of the patches work? if so, which one?

asiripanich commented 4 years ago

Hi Shankari,

Thank you for the investigation you have done. I’m waiting for @atton16 to look at the patches. In a few days, we will report back to you.

By the way, the incident reporting feature is still enable on my branch. If it is not used anymore (not that we have ever used it), can we disable that feature entirely on our branch?

asiripanich commented 4 years ago

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).

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.

The particular day that you were retrieving had 7 trips with 11 sections.

2020-01-02 09:56:42,890:DEBUG:140518462981888:finished querying values for ['analysis/cleaned_trip', 'analysis/cleaned_untracked'], count = 7
...
$ grep "mapped cleaned section" /tmp/webserver_log_gettrips | wc -l
      11

A simpler day with fewer trips (e.g. unimodal commute to/from work) should be much faster.

@asiripanich @atton16 In parallel with this investigation, can you try with a simpler day and confirm that the load time is much faster?

We 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.

shankari commented 4 years ago

By the way, the incident reporting feature is still enable on my branch.

@asiripanich I thought you had disabled all trip end notifications anyway. Where is the incident reporting feature enabled on your branch?

If it is not used anymore (not that we have ever used it), can we disable that feature entirely on our branch?

Of course!

asiripanich commented 4 years ago

oh wait that's not incident reporting I meant the correction feature you know the one that when you tap on the map and it gives you the options to select a smile face and a sad face. Is this feature being used in the section analysis step?

shankari commented 4 years ago

You mean in the detail screen, right? That is incident reporting. There was some thought of using a similar option to edit/correct sections but it never made it into master. You can remove it by commenting out the map click https://github.com/e-mission/e-mission-phone/blob/master/www/js/diary/detail.js#L72

I can do it for you and deploy, but I don't have time to test it. I guess you could test and then I could revert it back if it didn't work. Or else you can have @atton16 address it as part of the next set of changes.

asiripanich commented 4 years ago

@atton16 can do that for us. Thanks again @shankari! :)

shankari commented 4 years ago

I'm still debating whether that should be in master or not. Can you ask @atton16 to submit a PR to remove it on master as well? Then I'll check with the committee and decide. Right now, I am leaning towards removal.

asiripanich commented 4 years ago

Certainly.

shankari commented 4 years ago

@atton16 any updates on this?

atton16 commented 4 years ago

I have implemented the indexing patch. However with the existing database, it appears that no new index is created. So I decode your python code add the following index manually:

------ BEGINS INDEX RECORD ------ collection: Stage_usercache name: data.ts_-1 keys: 

{
    "data.ts" : -1
}

Sparse: true ------ ENDS INDEX RECORD ------

After implementation, @asiripanich reported that there is immediate performance improvement.

shankari commented 4 years ago

@atton16

I have implemented the indexing patch. However with the existing database, it appears that no new index is created.

The new index would have been created the next time the usercache was accessed - e.g. on /usercache/get or /usercache/put or when retrieving the trip diary from the server.

Did you try any of those operations before checking the index? Or did you check immediately after applying the patch?

atton16 commented 4 years ago

During the performance comparison test, I see the index shows up right after deletion. Now I know why it show up by itself.

To answer your question, I check immediately.

shankari commented 4 years ago

After implementation, @asiripanich reported that there is immediate performance improvement.

Great! Can you send the new logs (with the improvement)? If there are any other low-hanging performance improvements, we could try to address them as well.

shankari commented 4 years ago

During the performance comparison test, I see the index shows up right after deletion. Now I know why it show up by itself.

Also, you did a performance comparison test? What were the results?

asiripanich commented 4 years ago

@shankari will let you know the result soon. The tests we did yesterday were not entirely correct. We thought by manually removing the index of the usercache collection would be sufficient to make a before and after comparison. But we have just found out that the server reindexed the collection right after we had removed the index.

shankari commented 4 years ago

Yeah that's what the patch does - create the index if it doesn't exist :) If you want to really test before and after, you need to:

asiripanich commented 4 years ago

Yes that's exactly what we have planned to do.

asiripanich commented 4 years ago

The patch (solution 2) does improve diary loading time. Especially when there are answered trips, see 2020-02-02.

Screen Shot 2020-02-29 at 5 21 02 pm

ems.2020-02-29.patched.cellular.log ems.2020-02-29.patched.unsw-wifi.log ems.2020-02-29.unpatch.cellular.log

shankari commented 4 years ago

Great! For the record, can you also add the number of trips for each day, or plot response time v/s number of trips? I think that would be very interesting. Let me look at these logs to see if there is any other low hanging fruit for optimization.

shankari commented 4 years ago

Unfortunately, the logs only have the timestamps. @atton16 can you attach the full logs, as in https://github.com/e-mission/e-mission-docs/issues/488#issuecomment-570488847 so I can see if there is any other low-hanging fruit that we can fix? You should pick the worst case days (e.g. 2020-02-05).

atton16 commented 4 years ago

Here is the server log from unpatched case.

START 2020-02-29 05:56:03.844887 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:03.862232 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:03.866658 POST /timeline/getTrips/2020-02-01
START 2020-02-29 05:56:03.879095 POST /pipeline/get_complete_ts
START 2020-02-29 05:56:03.882683 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:56:04.167566 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.2883937358856201 
END 2020-02-29 05:56:04.409857 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.5648894309997559 
END 2020-02-29 05:56:04.413337 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.5510673522949219 
END 2020-02-29 05:56:04.424899 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.5421693325042725 
END 2020-02-29 05:56:04.701165 POST /timeline/getTrips/2020-02-01 c1793490-b0c5-44ed-8232-0ec56881e82f 0.834449291229248 
START 2020-02-29 05:56:07.924938 POST /timeline/getTrips/2020-02-02
START 2020-02-29 05:56:07.938049 POST /pipeline/get_complete_ts
START 2020-02-29 05:56:07.940889 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:07.943357 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:07.954191 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:56:08.236649 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.29323697090148926 
END 2020-02-29 05:56:08.236982 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.29605984687805176 
END 2020-02-29 05:56:08.721478 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.7833940982818604 
END 2020-02-29 05:56:08.903790 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.9495477676391602 
END 2020-02-29 05:56:09.177363 POST /timeline/getTrips/2020-02-02 c1793490-b0c5-44ed-8232-0ec56881e82f 1.2523677349090576 
START 2020-02-29 05:56:12.831669 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:12.833371 POST /pipeline/get_complete_ts
START 2020-02-29 05:56:12.838775 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:12.841748 POST /timeline/getTrips/2020-02-03
START 2020-02-29 05:56:12.845487 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:56:13.035844 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.2024226188659668 
END 2020-02-29 05:56:13.054290 POST /timeline/getTrips/2020-02-03 c1793490-b0c5-44ed-8232-0ec56881e82f 0.21250534057617188 
END 2020-02-29 05:56:13.184898 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3531475067138672 
END 2020-02-29 05:56:13.185780 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3469700813293457 
END 2020-02-29 05:56:13.209164 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.36362552642822266 
START 2020-02-29 05:56:16.469204 POST /pipeline/get_complete_ts
END 2020-02-29 05:56:16.601674 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.1324169635772705 
START 2020-02-29 05:56:16.973315 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:16.979804 POST /timeline/getTrips/2020-02-04
START 2020-02-29 05:56:16.985690 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:16.986783 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:56:17.313589 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3402223587036133 
END 2020-02-29 05:56:17.330788 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.34395670890808105 
END 2020-02-29 05:56:17.331202 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.34546732902526855 
END 2020-02-29 05:56:17.386193 POST /timeline/getTrips/2020-02-04 c1793490-b0c5-44ed-8232-0ec56881e82f 0.4063441753387451 
START 2020-02-29 05:56:20.672853 POST /timeline/getTrips/2020-02-05
START 2020-02-29 05:56:21.140049 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:21.158853 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:21.166342 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:21.176346 POST /pipeline/get_complete_ts
END 2020-02-29 05:56:21.338233 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.16183996200561523 
END 2020-02-29 05:56:21.468390 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.32828378677368164 
END 2020-02-29 05:56:21.496381 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3374760150909424 
END 2020-02-29 05:56:21.497042 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.33066701889038086 
END 2020-02-29 05:56:21.762920 POST /timeline/getTrips/2020-02-05 c1793490-b0c5-44ed-8232-0ec56881e82f 1.090010404586792 
START 2020-02-29 05:56:25.439904 POST /timeline/getTrips/2020-02-06
START 2020-02-29 05:56:25.450716 POST /pipeline/get_complete_ts
START 2020-02-29 05:56:25.453456 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:25.471080 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:25.479371 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:56:25.590367 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.13960528373718262 
END 2020-02-29 05:56:25.745201 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.26578187942504883 
END 2020-02-29 05:56:26.058255 POST /timeline/getTrips/2020-02-06 c1793490-b0c5-44ed-8232-0ec56881e82f 0.6182889938354492 
END 2020-02-29 05:56:26.363836 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.9103217124938965 
END 2020-02-29 05:56:26.399618 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.9285030364990234 
START 2020-02-29 05:56:29.560119 POST /pipeline/get_complete_ts
END 2020-02-29 05:56:29.691452 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.13128209114074707 
START 2020-02-29 05:56:30.049537 POST /timeline/getTrips/2020-02-07
START 2020-02-29 05:56:30.058741 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:30.061156 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:30.078335 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:56:30.392399 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.33360886573791504 
END 2020-02-29 05:56:30.396728 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.33553218841552734 
END 2020-02-29 05:56:30.400466 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3220813274383545 
END 2020-02-29 05:56:30.712025 POST /timeline/getTrips/2020-02-07 c1793490-b0c5-44ed-8232-0ec56881e82f 0.6624228954315186 
START 2020-02-29 05:56:34.517681 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:34.533193 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:56:34.542494 POST /pipeline/get_complete_ts
START 2020-02-29 05:56:34.551102 POST /timeline/getTrips/2020-02-01
START 2020-02-29 05:56:34.553870 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:56:34.719467 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.17693424224853516 
END 2020-02-29 05:56:34.871429 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.35369181632995605 
END 2020-02-29 05:56:34.884256 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3303365707397461 
END 2020-02-29 05:56:34.900661 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.36731886863708496
atton16 commented 4 years ago

Here is the server log from pathed case.

START 2020-02-29 05:50:02.829672 POST /timeline/getTrips/2020-02-01
START 2020-02-29 05:50:02.843865 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:02.869772 POST /pipeline/get_complete_ts
START 2020-02-29 05:50:02.880508 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:02.881864 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:50:03.252796 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.3829636573791504 
END 2020-02-29 05:50:03.433888 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.5519647598266602 
END 2020-02-29 05:50:03.445267 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.5647227764129639 
END 2020-02-29 05:50:03.445511 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.6016128063201904 
END 2020-02-29 05:50:03.597130 POST /timeline/getTrips/2020-02-01 c1793490-b0c5-44ed-8232-0ec56881e82f 0.7673735618591309 
START 2020-02-29 05:50:06.691402 POST /timeline/getTrips/2020-02-02
START 2020-02-29 05:50:06.695142 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:06.715511 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:06.724064 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:06.725678 POST /pipeline/get_complete_ts
END 2020-02-29 05:50:06.897577 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.1718578338623047 
END 2020-02-29 05:50:07.052585 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3370230197906494 
END 2020-02-29 05:50:07.062935 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.36775851249694824 
END 2020-02-29 05:50:07.083255 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3591434955596924 
END 2020-02-29 05:50:07.208076 POST /timeline/getTrips/2020-02-02 c1793490-b0c5-44ed-8232-0ec56881e82f 0.516620397567749 
START 2020-02-29 05:50:10.496283 POST /timeline/getTrips/2020-02-03
START 2020-02-29 05:50:10.506385 POST /pipeline/get_complete_ts
START 2020-02-29 05:50:10.521845 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:10.524613 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:10.540152 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:50:10.653272 POST /timeline/getTrips/2020-02-03 c1793490-b0c5-44ed-8232-0ec56881e82f 0.1569352149963379 
END 2020-02-29 05:50:10.784669 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.25998497009277344 
END 2020-02-29 05:50:11.320336 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.8139104843139648 
END 2020-02-29 05:50:11.483284 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.943082332611084 
END 2020-02-29 05:50:11.488424 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.966533899307251 
START 2020-02-29 05:50:15.306476 POST /pipeline/get_complete_ts
START 2020-02-29 05:50:15.310299 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:15.329592 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:15.330778 POST /timeline/getTrips/2020-02-04
START 2020-02-29 05:50:15.336654 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:50:15.500299 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.19377708435058594 
END 2020-02-29 05:50:15.659791 POST /timeline/getTrips/2020-02-04 c1793490-b0c5-44ed-8232-0ec56881e82f 0.32895493507385254 
END 2020-02-29 05:50:15.667677 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.33803296089172363 
END 2020-02-29 05:50:15.668257 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3579251766204834 
END 2020-02-29 05:50:15.690224 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.353501558303833 
START 2020-02-29 05:50:19.468649 POST /pipeline/get_complete_ts
START 2020-02-29 05:50:19.499050 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:19.501449 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:19.504306 POST /timeline/getTrips/2020-02-05
START 2020-02-29 05:50:19.561548 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:50:19.605540 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.13683629035949707 
END 2020-02-29 05:50:19.771788 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.2702932357788086 
END 2020-02-29 05:50:19.960819 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.46172261238098145 
END 2020-02-29 05:50:19.961970 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.40038609504699707 
END 2020-02-29 05:50:20.372261 POST /timeline/getTrips/2020-02-05 c1793490-b0c5-44ed-8232-0ec56881e82f 0.8678953647613525 
START 2020-02-29 05:50:23.944765 POST /timeline/getTrips/2020-02-06
START 2020-02-29 05:50:23.973254 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:23.976267 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:23.987697 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:23.989293 POST /pipeline/get_complete_ts
END 2020-02-29 05:50:24.163844 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.17451047897338867 
END 2020-02-29 05:50:24.302116 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.31436681747436523 
END 2020-02-29 05:50:24.304832 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3285245895385742 
END 2020-02-29 05:50:24.315597 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.34230852127075195 
END 2020-02-29 05:50:24.476451 POST /timeline/getTrips/2020-02-06 c1793490-b0c5-44ed-8232-0ec56881e82f 0.5316152572631836 
START 2020-02-29 05:50:27.766643 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:27.777380 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:27.778371 POST /timeline/getTrips/2020-02-07
START 2020-02-29 05:50:27.790291 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:27.817094 POST /pipeline/get_complete_ts
END 2020-02-29 05:50:27.977204 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.16006040573120117 
END 2020-02-29 05:50:28.131511 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.35406947135925293 
END 2020-02-29 05:50:28.143442 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3767373561859131 
END 2020-02-29 05:50:28.144458 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.3541250228881836 
END 2020-02-29 05:50:28.273363 POST /timeline/getTrips/2020-02-07 c1793490-b0c5-44ed-8232-0ec56881e82f 0.49494457244873047 
START 2020-02-29 05:50:32.264096 POST /timeline/getTrips/2020-02-01
START 2020-02-29 05:50:32.275805 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:32.278419 POST /pipeline/get_complete_ts
START 2020-02-29 05:50:32.280918 POST /datastreams/find_entries/timestamp
START 2020-02-29 05:50:32.291330 POST /datastreams/find_entries/timestamp
END 2020-02-29 05:50:32.464357 POST /pipeline/get_complete_ts c1793490-b0c5-44ed-8232-0ec56881e82f 0.1858985424041748 
END 2020-02-29 05:50:32.633023 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.34163570404052734 
END 2020-02-29 05:50:32.640850 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.35989975929260254 
END 2020-02-29 05:50:32.655164 POST /datastreams/find_entries/timestamp c1793490-b0c5-44ed-8232-0ec56881e82f 0.37932395935058594
shankari commented 4 years ago

@atton16 I was looking for the full logs. Please see the link to the previous comment. https://github.com/e-mission/e-mission-docs/issues/488#issuecomment-570488847