westnordost
commented
3 years ago Can you show the log?
Closed Helium314 closed 3 years ago
westnordost
commented
3 years ago Can you show the log?
Helium314
commented
3 years ago Answered crossing type (slow), opening hours (fast), building type (slow)
OsmQuestController: Created AddWheelchairAccessBusiness for NODE#8118300817
OsmQuestController: Created 1 quests for 1 updated elements in 0.1s
OsmQuestController: Persisted 1 new and removed 1 already resolved quests in 0.0s
QuestController: Solved a AddBuildingType quest: MODIFY "building"="yes" -> "building"="detached"
OsmQuestController: AddHousenumber requires surrounding map data to determine applicability to WAY#846977295
CursorWindow: Window is full: requested allocation 60 bytes, free space 55 bytes, window size 2097152 bytes
CursorWindow: Window is full: requested allocation 60 bytes, free space 35 bytes, window size 2097152 bytes
CursorWindow: Window is full: requested allocation 60 bytes, free space 3 bytes, window size 2097152 bytes
CursorWindow: Window is full: requested allocation 60 bytes, free space 31 bytes, window size 2097152 bytes
CursorWindow: Window is full: requested allocation 4 bytes, free space 0 bytes, window size 2097152 bytes
CursorWindow: Window is full: requested allocation 1 bytes, free space 0 bytes, window size 2097152 bytes
CursorWindow: Window is full: requested allocation 1 bytes, free space 0 bytes, window size 2097152 bytes
CursorWindow: Window is full: requested allocation 60 bytes, free space 39 bytes, window size 2097152 bytes
MapDataController: Fetched 111 elements and geometries in 41204ms
OsmQuestController: Created AddHousenumber for WAY#846977295
OsmQuestController: Created AddBuildingLevels for WAY#846977295
OsmQuestController: Created 2 quests for 1 updated elements in 41.3s
OsmQuestController: Persisted 2 new and removed 1 already resolved quests in 0.0sI took the liberty to edit that log to only show the relevant parts. The most relevant parts are:
AddHousenumber requires surrounding map data to determine applicability to WAY#846977295
Fetched 111 elements and geometries in 41204msSo, disclaimer: v32.0 is more slow and more demanding on resources. Because this is what happens:
questType.isApplicableTo(element) is called, which is reasonably fast. However, whenever that method returns null, it means that information about the surrounding elements are necessary to answer that. So what the app then does is to fetch the surrounding area (20m or so around the element) from the database and then check if the updated element is amongst those returned by questType.getApplicableElements(mapData).The reason why it is fast for AddWheelchairAccessBusiness is because no quest returned null on questType.isApplicableTo(element) but all either true or false. In this case, all returned false except for one quest.
For AddBuildingType, the AddHousenumber quest returned null for that method because it needs information about surrounding geometry. As you see in the log, 111 elements and geometries where fetched from database. On my device, this lookup takes about 100ms. This is already long and I wondered about why it takes so long. 40000ms is outrageous for 111 elements.
The main reason that it takes long for your device seem to be some memory constraints regarding the CursorWindow. I will look into what that means next.
westnordost
commented
3 years ago The map data geometry is fetched from the database using a bounding box. There is no index on the min latitude, min longitude, max latitude and max longitude of each geometry in the element geometry table because I am not sure if an index would help on a select statement like SELECT * FROM table WHERE xmin >= 0.1 AND xmax <= 0.2 AND ymin >= 0.1 AND ymax <= 0.2, so I did a test.
I created a little kotlin script that outputs a test.sql that creates a table with entries that also have a "bounding box":
fun main() {
File("test.sql").printWriter().use { out ->
out.println("BEGIN TRANSACTION;")
out.println("""
CREATE TABLE "test" (
"i" INTEGER NOT NULL,
"xmin" NUMERIC NOT NULL,
"ymin" NUMERIC NOT NULL,
"xmax" NUMERIC NOT NULL,
"ymax" NUMERIC NOT NULL,
PRIMARY KEY("i" AUTOINCREMENT)
);
""".trimIndent())
for(i in 0..500000) {
out.println("INSERT INTO test (xmin,ymin,xmax,ymax) values (${Random.nextDouble()},${Random.nextDouble()},${Random.nextDouble()},${Random.nextDouble()});")
}
out.println("COMMIT TRANSACTION;")
}
}On my computer, doing a query on a database created from that test.sql file like
SELECT * FROM test WHERE xmin >= 0.1 AND xmax <= 0.2 AND ymin >= 0.1 AND ymax <= 0.2takes about 100ms. If I add an index like this
CREATE INDEX minmax on test (xmin, xmax, ymin, ymax)it takes about 50ms. So, an index in SQLite also works with >= etc operators. That's good, so I will add an index.
However, this is likely not the main problem, the main problem seem to be some contraints on the cursor window. Will look into that next.
Helium314
commented
3 years ago Thanks for the explanation.
What I wonder: why is this lookup much faster
westnordost
commented
3 years ago Maybe the fetching from DB (=creating of the objects) itself is somehow hugely inefficient
westnordost
commented
3 years ago I pushed the creations of the indexes to master. I'd be interested to know how much this speeds this up for you. (You need to uninstall and reinstall the app.) If possible, it would be great if you used the the exact same element for the test.
westnordost
commented
3 years ago Did a random test myself. The times are still really slow:
Fetched 241 geometries in 216ms
Fetched 206 nodes in 125ms
Fetched 22 ways in 92ms
Fetched 13 relations in 205msDid some more detailed performance measuring (after indexing applied) at that location. Of the total time spent:
So, SQL efficiency is not really the problem. Or if it is, it's in the iterating the SQL cursor, which can't be made any faster. Most time (83%) is spent in application code: instantiating the data. Of these a third alone is spent on deserializing the element tags.
Since the data classes will be exchanged with pure kotlin ones and the serialization library is exchanged with kotlinx-serialization which is not based on Java Reflection but on the other hand serializes to a less compact format (JSON), the measurements may be different on that branch. Will take another measurement on that branch.
Helium314
commented
3 years ago Here is a log with the latest change: started the app after re-install, downloaded quests, answered the same 2 quests as before (I think), answer a building type quest near the south edge of downloaded area, download a different dense area, answer building type quest there (the problem is clearly not (only) the number of nearby elements
westnordost
commented
3 years ago so, no difference
westnordost
commented
3 years ago I have been doing performance testings all day long, but it is really hard because the times measured are quite elusive.
For example, if I do one and the same thing - answer that a house is a detached (this one: https://www.openstreetmap.org/way/58502870#map=19/53.54687/9.99737) (then undo), then answer that again etc, the times measured vary from 300ms to 90ms at one and the same location. Though, what is consistent is that the first fetching takes longest, the second is shorter and then usually on the third call, it's consistently down to 90ms.
And it is the same for the current master branch and the kotlinx-serialization branch (pure kotlin data classes + replaced Kryo serialization library with kotlinx-serialization-json)
I also checked if the Cursor.get*(columnName: String) methods used by the db wrapper class are maybe slow because they always have to string-compare the columnName and then iterate the array of column names in the result, but no, the SQLiteCursor properly caches the colum names in a map.
westnordost
commented
3 years ago Also, the times measured on what is taking long are always constant, in the sense that if the call takes 300ms, everything (SQLite query, instantiation or deserialization) takes longer and if the call takes 90ms, everything is faster. đŸ˜
westnordost
commented
3 years ago So I am out of ideas. 80ms is good, 300ms is... okay. 40000ms is unusable. Though that particular explosion of time it takes to fetch a few hundred elements from the database seems to be only reproducible on your device.
I mean, when quests are displayed, a couple of thousand quests are fetched from the database - that doesn't seem to be a problem on your device? Or is your device trying to fetch this data from database for 5 minutes and during that time, any other larger database operation will also take such an amount of time?
Anyway, I fear to advance with this issue, I rely on your help. You yourself must measure the operation to find what particular element of it takes this much time.
matkoniecz
commented
3 years ago Though that particular explosion of time it takes to fetch a few hundred elements from the database seems to be only reproducible on your device.
Something similar happened to me when I started testing new version (freeze of app for several seconds on download), then failed to appear again. So I decided to blame phone for being Xiaomi-quality.
I initially got scared that new code is causing massive slowdowns then it failed to appear ever again.
westnordost
commented
3 years ago hmmm đŸ˜Ÿ
Helium314
commented
3 years ago Anyway, I fear to advance with this issue, I rely on your help. You yourself must measure the operation to find what particular element of it takes this much time.
Well, definitely the DB size that is important, as (so far) it only happens if I download many elements at once. Do you (or anyone else) get any of these "Window is full" messages after creating a 25+ MB DB at initial download?
I'm currently trying to split the download into smaller areas, hoping that it might cause geographically close elements to be "closer" in the DB (might be obviously useless; I have no clue how such a DB is organized internally and simply imagine a huge spreadsheet)
Helium314
commented
3 years ago Hmm, this is not really helping. I tried splitting the bbox into four here, which massively increased download time. There is some improvement when answering the building type quest, but 33 instead of 43 sec is still way too much.
westnordost
commented
3 years ago No, I don't get these messages.
I think the best way would be if you first measured and logged the time it takes to fetch the geometry, the elements etc from DB
Am 27. April 2021 07:12:03 MESZ schrieb Helium314 @.***>:
Anyway, I fear to advance with this issue, I rely on your help. You yourself must measure the operation to find what particular element of it takes this much time.
Well, definitely the DB size that is important, as (so far) it only happens if I download many elements at once. Do you (or anyone lese) get any of these "Window is full" messages after creating a 25+ MB DB at initial download?
I'm currently trying to split the download into smaller areas, hoping that it might cause geographically close elements to be "closer" in the DB (might be obviously useless; I have no clue how such a DB is organized internally and simply imagine a huge spreadsheet)
-- You are receiving this because you were assigned. Reply to this email directly or view it on GitHub: https://github.com/streetcomplete/StreetComplete/issues/2803#issuecomment-827316970
-- Diese Nachricht wurde von meinem Android-Gerät mit K-9 Mail gesendet.
Helium314
commented
3 years ago Splitting the download into 16 parts decreases the fetch time to 5 sec, but only fetches 50 elements instead of 100+ (not sure how relevant this is, the number is different every time). So organizing the DB "the right way" should help. But on how to do this, I have no idea.
westnordost
commented
3 years ago What download? This ticket is about that answering quests is really slow, isn't it? That has nothing to do with the download.
westnordost
commented
3 years ago not sure how relevant this is, the number is different every time
This is extremely relevant though, as this might point to another bug. Maybe log the BBOX the fetch is being made for.
westnordost
commented
3 years ago As said, please don't blindly try around such tings, first step should be what part of the process is the one thing that takes long. Then we can optimize.
Helium314
commented
3 years ago What download? This ticket is about that answering quests is really slow, isn't it? That has nothing to do with the download.
As written above: this problem appears inside large areas downloaded at once (in a single download). Not for any specific element. If I only download a tiny area at full zoom, answering the quest for the same element is done in about a second. So in some sense it HAS to do with the download (or my current impression: how the downloaded data is put into the DB)
Helium314
commented
3 years ago This is extremely relevant though, as this might point to another bug. Maybe log the BBOX the fetch is being made for.
Two attempts, one fetched 105 elements, one 41. Both used the same bbox (logged inside the house number quest)
westnordost
commented
3 years ago Hm okay, maybe you could fetch that exact same box with JOSM and see where is the difference. Maybe too many elements are fetched from DB? Or too few?
Helium314
commented
3 years ago I never used JOSM. Is is possible using overpass turbo? Bounding box is 16.419545934620487,48.18712161656099,16.420325067297767,48.18763698312338
westnordost
commented
3 years ago Well, you can get it directly: https://api.openstreetmap.org/api/0.6/map?bbox=16.419545934620487,48.18712161656099,16.420325067297767,48.18763698312338
westnordost
commented
3 years ago So that's 25 nodes, 4 ways. In total 29 elements. And the DB fetch request returns 41 or 105? That is suspicious. Could you log which ids it returns?
Helium314
commented
3 years ago 105 fetched elements:
[ElementKey(type=WAY, id=366748359), ElementKey(type=WAY, id=235677554), ElementKey(type=WAY, id=513295192), ElementKey(type=RELATION, id=369791), ElementKey(type=RELATION, id=7449070), ElementKey(type=RELATION, id=9467077), ElementKey(type=WAY, id=891579199), ElementKey(type=WAY, id=28281701), ElementKey(type=RELATION, id=89652), ElementKey(type=WAY, id=8078895), ElementKey(type=RELATION, id=1406382), ElementKey(type=WAY, id=545293423), ElementKey(type=RELATION, id=6249868), ElementKey(type=RELATION, id=6249870), ElementKey(type=RELATION, id=6249864), ElementKey(type=RELATION, id=6249865), ElementKey(type=WAY, id=134568224), ElementKey(type=RELATION, id=1991442), ElementKey(type=RELATION, id=7917320), ElementKey(type=RELATION, id=1991416), ElementKey(type=RELATION, id=7917315), ElementKey(type=WAY, id=316469812), ElementKey(type=WAY, id=54442135), ElementKey(type=WAY, id=390598544), ElementKey(type=RELATION, id=5847058), ElementKey(type=RELATION, id=5847065), ElementKey(type=RELATION, id=9337249), ElementKey(type=RELATION, id=9337356), ElementKey(type=RELATION, id=9522506), ElementKey(type=RELATION, id=9208722), ElementKey(type=RELATION, id=9333762), ElementKey(type=RELATION, id=9334322), ElementKey(type=RELATION, id=9351571), ElementKey(type=RELATION, id=9627824), ElementKey(type=RELATION, id=9639285), ElementKey(type=RELATION, id=9644847), ElementKey(type=RELATION, id=9649661), ElementKey(type=RELATION, id=9667932), ElementKey(type=RELATION, id=10751523), ElementKey(type=RELATION, id=9352323), ElementKey(type=RELATION, id=9386915), ElementKey(type=RELATION, id=9463140), ElementKey(type=RELATION, id=9463143), ElementKey(type=RELATION, id=9660076), ElementKey(type=RELATION, id=10760607), ElementKey(type=RELATION, id=9673461), ElementKey(type=RELATION, id=9331466), ElementKey(type=RELATION, id=9445741), ElementKey(type=RELATION, id=194662), ElementKey(type=RELATION, id=2399354), ElementKey(type=WAY, id=131477211), ElementKey(type=WAY, id=628054635), ElementKey(type=WAY, id=131491267), ElementKey(type=WAY, id=41671290), ElementKey(type=WAY, id=3220522), ElementKey(type=RELATION, id=207308), ElementKey(type=RELATION, id=2209339), ElementKey(type=RELATION, id=1990594), ElementKey(type=RELATION, id=5847288), ElementKey(type=RELATION, id=7917329), ElementKey(type=WAY, id=655420088), ElementKey(type=WAY, id=147444470), ElementKey(type=RELATION, id=9191779), ElementKey(type=RELATION, id=9333653), ElementKey(type=RELATION, id=9334324), ElementKey(type=RELATION, id=9337248), ElementKey(type=RELATION, id=9337355), ElementKey(type=RELATION, id=9351570), ElementKey(type=RELATION, id=9352324), ElementKey(type=RELATION, id=9386914), ElementKey(type=RELATION, id=9463142), ElementKey(type=RELATION, id=9463144), ElementKey(type=RELATION, id=9627825), ElementKey(type=RELATION, id=9639286), ElementKey(type=RELATION, id=9644848), ElementKey(type=RELATION, id=9649660), ElementKey(type=RELATION, id=9660077), ElementKey(type=RELATION, id=9667933), ElementKey(type=RELATION, id=9673460), ElementKey(type=RELATION, id=10751524), ElementKey(type=RELATION, id=10760608), ElementKey(type=RELATION, id=11817492), ElementKey(type=RELATION, id=9227796), ElementKey(type=RELATION, id=9331467), ElementKey(type=WAY, id=133764170), ElementKey(type=RELATION, id=9522507), ElementKey(type=WAY, id=885876130), ElementKey(type=WAY, id=740277030), ElementKey(type=NODE, id=7903379312), ElementKey(type=WAY, id=846977295), ElementKey(type=NODE, id=6931015492), ElementKey(type=WAY, id=885876131), ElementKey(type=NODE, id=6931015506), ElementKey(type=WAY, id=740277033), ElementKey(type=NODE, id=7903379311), ElementKey(type=NODE, id=6931015493), ElementKey(type=NODE, id=7903379310), ElementKey(type=WAY, id=658305257), ElementKey(type=NODE, id=6164794952), ElementKey(type=NODE, id=7903379309), ElementKey(type=NODE, id=5517629213), ElementKey(type=NODE, id=6931015503), ElementKey(type=NODE, id=6164794948), ElementKey(type=NODE, id=8615285130), ElementKey(type=NODE, id=6164794958)]41 fetched elements:
[ElementKey(type=WAY, id=366748359), ElementKey(type=WAY, id=316469812), ElementKey(type=WAY, id=54442135), ElementKey(type=WAY, id=390598544), ElementKey(type=RELATION, id=5847058), ElementKey(type=RELATION, id=5847065), ElementKey(type=RELATION, id=1991416), ElementKey(type=RELATION, id=1991442), ElementKey(type=RELATION, id=7917315), ElementKey(type=RELATION, id=7917320), ElementKey(type=WAY, id=131477211), ElementKey(type=RELATION, id=6249864), ElementKey(type=RELATION, id=6249865), ElementKey(type=RELATION, id=6249868), ElementKey(type=RELATION, id=6249870), ElementKey(type=WAY, id=131491267), ElementKey(type=WAY, id=41671290), ElementKey(type=WAY, id=3220522), ElementKey(type=RELATION, id=207308), ElementKey(type=RELATION, id=2209339), ElementKey(type=WAY, id=655420088), ElementKey(type=WAY, id=133764170), ElementKey(type=WAY, id=885876130), ElementKey(type=WAY, id=740277030), ElementKey(type=NODE, id=7903379312), ElementKey(type=WAY, id=846977295), ElementKey(type=NODE, id=6931015492), ElementKey(type=WAY, id=885876131), ElementKey(type=NODE, id=6931015506), ElementKey(type=WAY, id=740277033), ElementKey(type=NODE, id=7903379311), ElementKey(type=NODE, id=6931015493), ElementKey(type=NODE, id=7903379310), ElementKey(type=WAY, id=658305257), ElementKey(type=NODE, id=6164794952), ElementKey(type=NODE, id=7903379309), ElementKey(type=NODE, id=5517629213), ElementKey(type=NODE, id=6931015503), ElementKey(type=NODE, id=6164794948), ElementKey(type=NODE, id=8615285130), ElementKey(type=NODE, id=6164794958)]So a lot of relations are not present in the 41 elements (didn't check whether anything else is missing)
Additionally my logs show that the slow part is in relationDao.getAll
westnordost
commented
3 years ago RelationDao.getAll has two parts: Getting relation members and getting relations. And then, of course, this can be measured also in more detail: What is the slow part, the query as such, or the instantiation of the objects?
Helium314
commented
3 years ago Yes, that was the case for every function I found taking long so far. Will continue later or maybe tomorrow, don't have time now.
westnordost
commented
3 years ago I will analyze what is the difference between the 105-element result and the 29 element-result from the OSMAPI
westnordost
commented
3 years ago Yes, that was the case for every function I found taking long so far.
Which part was slow?
westnordost
commented
3 years ago Anyway, regarding the "too many elements", I fear this is currently at least the intended behavior. It looks like the OSM API only looks for which nodes are within the given bounding box, and then returns all elements which have these nodes as their member.
StreetComplete looks at whose element's bounding boxes intersect with the given bounding box. This why it is more. Why does StreetComplete not simply mimic the behavior of the OSM API? Because of this case:
StreetComplete should not ask if the shown road has a cycleway or not, because a separately mapped cycleway is near. Let's say SC scans this area for quests. Then, if the app would not take into account any geometry that crosses that bbox but only those that have nodes inside the bbox, SC would not find the cycleway. This is why StreetComplete currently fetches all elements from the database whose bounding box intersect with a given bounding box.
So, already without the relations, this is what SC will fetch from the database:
(
node(id:7903379312,6931015492,6931015506,7903379311,6931015493,7903379310,6164794952,7903379309,5517629213,6931015503,6164794948,8615285130,6164794958);
way(id:133764170,885876130,740277030,740277033,658305257,846977295,885876131,655420088,147444470,131477211,628054635,131491267,41671290,3220522,316469812,54442135,390598544,134568224,8078895,545293423,366748359,235677554,513295192,891579199,28281701);
);
out geom;The bounding box of all these ways intersect with the given bounding box.
With relations, it gets worse of course.
And I guess we found the reason for the slowness, the reason why the times are very different depending on the current location and why the number of elements returned differs depending on how many other elements you already downloaded.
Question is, what to do about it.
matkoniecz
commented
3 years ago Maybe exclude megarelations that are not going to be useful for any quests. From my lunar_assembler (where I did it to remove horrific spam making debugging a nightmare):
https://github.com/matkoniecz/lunar_assembler/blob/master/lunar_assembler.js#L213
[type!=route][type!=parking_fee][type!=waterway][type!=boundary][boundary!=administrative][boundary!=religious_administration]
Or maybe just have whitelist for relations and accept only useful ones? multipolygon - is there anything else?
EDIT: at least associated street relations are taking part in exclusion for street address quest.
EDIT2: though it would complicate splitting of such ways, probably downloading them but not all of their elements would work...
Helium314
commented
3 years ago Which part was slow?
I put some log entries to find the slow lines, which lead me to a different function where I put log entries to find the slow lines, which lead me to a different function... so I was referring to "RelationDao.getAll has two parts:" and meant that every function I had investigated so far had several parts and I was trying to find the slow one.
Sorry for writing this in a confusing way.
Will have a closer look at RelationDao.getAll now
And I guess we found the reason for the slowness, the reason why the times are very different depending on the current location and why the number of elements returned differs depending on how many other elements you already downloaded.
So SC is fetching every element in the DB that belongs to any of the nearby relations?
Helium314
commented
3 years ago The slow part of RelationDao.getAll is
db.query(NAME_MEMBERS, where = "$ID IN ($idsString)", orderBy = "$ID, $INDEX") { c ->
val members = membersByRelationId.getOrPut(c.getLong(ID)) { ArrayList() }
members.add(OsmRelationMember(
c.getLong(REF),
c.getString(ROLE),
Element.Type.valueOf(c.getString(TYPE))
))
}Would it be feasible to only put elements in the DB that are actually used in any quest? E.g. street lamps and boundaries are not used (I think)
westnordost
commented
3 years ago So SC is fetching every element in the DB that belongs to any of the nearby relations?
No, just the relations (not its elements) that intersect with the bbox. And implictly the geometry of these. And turns out, a lot of relations intersect, especially those with lots and lots of members.
Would it be feasible to only put elements in the DB that are actually used in any quest? E.g. street lamps and boundaries are not used (I think)
Haha, well yes, that is feasible: Just use v31 and earlier. The whole point of the architecture change made for v32 was that the OSM data is kept independent of quests and quests are just generated from these.
smichel17
commented
3 years ago So, SQL efficiency is not really the problem. Or if it is, it's in the iterating the SQL cursor, which can't be made any faster.
I wonder if this is true. Here's the code that @Helium314 identified as slow, again:
query essentially calls this:
And toSequence() is an extension function here:
The first thing is that toSequence() is returning a List, not a Sequence, so at worst there's an extra .toList() call on the end and at best we can parallelize a bit. Having just read through the coroutines docs, I think this might be the use case for flows. Anyway, need to head to bed now; I may spend a little more time banging my head against this tomorrow.
Helium314
commented
3 years ago Here's the code that @Helium314 identified as slow, again:
some update here: added some more logging; the slow part is definitley the db query and not the { cursor -> ... } part
smichel17
commented
3 years ago @Helium314 To clarify, you did basically this, and the first line was slow?
// save time
val query = db.query(false, table, columns, where, strArgs, groupBy, having, orderBy, limit)
// Output time spent
val mapped = query.toSequence(transform).toList()
// Output time spent
return mappedI am confused how that jives with @westnordost's measurements in https://github.com/streetcomplete/StreetComplete/issues/2803#issuecomment-826824778
- 17% on waiting for the SQL queries to complete
- 27% solely on deserializing the element tags using Kryo
- 56% on iterating the SQL result cursor and instantiating the objects
Is the query 17%, or is it the majority of the time?
Helium314
commented
3 years ago What I did was something like:
Log.i("relationdao","1")
db.query(NAME_MEMBERS, where = "$ID IN ($idsString)", orderBy = "$ID, $INDEX") { cursor ->
Log.i("relationdao","2")
val members = membersByRelationId.getOrPut(cursor.getLong(ID)) { ArrayList() }
Log.i("relationdao","3")
members.add(RelationMember(
ElementType.valueOf(cursor.getString(TYPE)),
cursor.getLong(REF),
cursor.getString(ROLE)
))
Log.i("relationdao","4")
}
Log.i("relationdao","5")Times are in the system log anyway.
What I got was 1, then repeated spam of 2,3,4, a "CursorWindow: Window is full" message, repeated spam of 2,3,4, CursorWindow,... and 2,3,4,5 in the end. The long time was always spend between 4 and 2, but only if there was a "CursorWindow: Window is full" message.
@westnordost's measurement was on a different device. I guess if I used a small db I would see similar values.
westnordost
commented
3 years ago Ok I measured it like this:
var t1 = 0L
var t2 = 0L
val start1 = System.currentTimeMillis()
db.query(NAME_MEMBERS, where = "$ID IN ($idsString)", orderBy = "$ID, $INDEX") { cursor ->
val start2 = System.currentTimeMillis()
val members = membersByRelationId.getOrPut(cursor.getLong(ID)) { ArrayList() }
members.add(RelationMember(
ElementType.valueOf(cursor.getString(TYPE)),
cursor.getLong(REF),
cursor.getString(ROLE)
))
t2 += System.currentTimeMillis() - start2
}
t1 = System.currentTimeMillis() - start1
Log.i("relationdao","fetched ${membersByRelationId.values.flatten().size} relation members in total time: $t1, of that, instantiation time: $2")and same for getting the relations
smichel17
commented
3 years ago Ok, I've done / am doing some additional profiling. Here's the code, in AndroidDatabase.kt line 45:
override fun <T> query(
table: String,
columns: Array<String>?,
where: String?,
args: Array<Any>?,
groupBy: String?,
having: String?,
orderBy: String?,
limit: String?,
distinct: Boolean,
transform: (CursorPosition) -> T
): List<T> {
val strArgs = args?.primitivesArrayToStringArray()
val s = System.currentTimeMillis();
val query = db.query(false, table, columns, where, strArgs, groupBy, having, orderBy, limit)
val t1 = System.currentTimeMillis() - s;
val trans = query.toSequence(transform)
val total = System.currentTimeMillis() - s;
val t2 = total - t1
fun pc(part: Long): String {
return "${(Math.round((part.toFloat()/total.toFloat())*100f*100f)/100f)}%"
}
if (total > 10L) {
android.util.Log.i("queryperf", "${trans.size} ${table} in ${total}ms ( ${pc(t1)} query | ${pc(t2)} transform ) -- WHERE ${where}")
}
return trans.toList()
}The total > 10L is to filter out a bunch of spam, since this runs for all queries, not just the ones we're interested in. This is also why I included the table and the WHERE clause, to have some idea of which query we're actually looking at.
Here's one, probably unrelated query that stood out to me, 1.7 seconds seems like an awfully long time for a query that doesn't actually find anything.
0 osm_note_edits in 1708ms ( 99.94% query | 0.06% transform ) -- WHERE synced = 0This is definitely the slow query. First line is when I ran it after downloading only the immediate area, second line is after scrolling around a lot and downloading more stuff, particularly around the roads highlighted in @westnordost's image above
11343 osm_relation_members in 48ms ( 0.0% query | 100.0% transform ) -- WHERE id IN (123822,28931,9103125,1746482,2390138,2872789,1395417,296011,231965,318406,2653230,9038695,1728112,5341494,6679987,2599010,2795128,1928240,1728102,2599011,388722,156547,110485,1643221,1643324,10586913,531557,106800,1103658,61612,297201,1540437,1660619,9345802,7397711,3009401,3009402,3009403,1660618,1660621,5453603,5454170,9345803,326858)
108492 osm_relation_members in 1457ms ( 0.0% query | 100.0% transform ) -- WHERE id IN (123822,67444,1788865,1856647,3229345,3436972,3898004,4458238,4458993,5515482,6188945,6188946,6193557,6193559,6354183,6421072,7819672,9352029,1083201,2178679,2947220,3134320,3310117,3431945,6188944,6188947,6193558,6309270,6354182,6421073,6864466,8865584,9352200,9477227,9477481,9491221,9511959,8396995,9990462,10080382,10773769,132517,9464943,9990461,10773770,5454170,9345803,1727352,1727355,233959,2795128,231965,61612,9345802,1727350,1727354,5754040,10077366,10330274,5754039,9238147,10329506,1395417,9133226,1749805,3349852,3389508,385668,31584,392042,2599011,2599010,229823,28931,9103125,10512337,1746482,10512335,2872789,2390138,297201,2089730,3779840,5455739,8865697,5429644,3779841,5454292,8885541,5453603,2064636,2653230,9038695,1728112,5341494,6679987,1728102,388722,156547,8543211,12121059,65828,12121061,110485,1643221,1643324,10586913,106800,1103658,1540437,1660619,7397711,3009401,3009402,3009403,1660618,1660621,326858)108492 osm_relation_members
It's the sheer volume. The bounding box of 117 relations intersects with that area around that building?? Whoa, what is all that?
smichel17
commented
3 years ago Is it possible to include all the relations, but filter the members by proximity? It might be important to know about nodes just outside the bounding box, but surely not those which are kilometers away.
westnordost
commented
3 years ago 0 osm_note_edits in 1708ms ( 99.94% query | 0.06% transform ) -- WHERE synced = 0
pretty sure this was just coincidence, for example another long running db operation was blocking access to the db.
IIRC, by default, SQLite does not have Write-Ahead Logging enabled and if I understood correctly, reading from db is blocked while a write operation takes places in non-WAL mode.
westnordost
commented
3 years ago Is it possible to include all the relations, but filter the members by proximity?
No. Note, that each member is only element type + element id + role string, not any more information.
After downloading a large area containing many quests, answering some quests takes very long (in my case this was done automatically after first app start, but also happens when zooming out and starting a manual scan). Especially for building or crossing quests, on my S4 Mini it takes some 30 seconds to for the pin to be removed. In this time I can't open any other quests, SC usage is basically blocked (panning/zooming the map is still possible without noticable slowdowns). Other quests like opening hours do not have this problem. Interestingly, answering quests near the southern edge of the scanned area is much faster than in other regions.
When "leaving" this area, i.e. scrolling somewhere far away, manually scanning and answering quests is fast (less than a second). The southern edge of the new area might be a little bit faster, not sure.
Sometimes after doing stuff "somewhere else", anwering quests inside the initial scan area is faster (maybe 10 seconds instead of 30 for the same element), but still slower than outside. I haven't yet found a way of reproducing this.