Closed Bug 1194023 Opened 4 years ago Closed 4 years ago

3,800 instances of "WARNING: Suboptimal indexes for the SQL statement" emitted from storage/mozStoragePrivateHelpers.cpp during linux64 debug testing

Categories

(Toolkit :: Storage, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla44
Tracking Status
firefox44 --- fixed

People

(Reporter: erahm, Assigned: erahm)

References

(Blocks 1 open bug)

Details

Attachments

(2 files)

This is the #3 most verbose warning.

> WARNING: Suboptimal indexes for the SQL statement 0xNNNNNNNNNNNN (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 109

There are over 3,800 variations of the warning [1] emitted during linux64 debug testing.

In it's current form it doesn't provide much value; printing the sql statement's pointer provides no actionable data. It also adds more overhead [2] to already slow debug builds.

We *can* turn on dumping of the actual SQL statement by #defining MOZ_STORAGE_SORTWARNING_SQL_DUMP, which is somewhat more useful. I would argue that we should not warn at all unless that value is #defined.

I did a try run w/ it enabled, the most egregious output is included below, if someone is feeling proactive we could split out blocking bugs to fix those instances.

> 996 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `SELECT ClientID, ItemType FROM moz_cache WHERE Key = ? ORDER BY LastFetched DESC, LastModified DESC;` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 984 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `SELECT ns.ClientID, ns.ItemType FROM  moz_cache_namespaces AS ns JOIN moz_cache_groups AS groups  ON ns.ClientID = groups.ActiveClientID WHERE ns.NameSpace <= ?1 AND ?1 GLOB ns.NameSpace || '*' ORDER BY ns.NameSpace DESC, groups.ActivateTimeStamp DESC;` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 113 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `SELECT url, guid, MAX(visit_date) AS visit_date,
> MAX(IFNULL(MIN(p_id, 1), MIN(v_id, 0))) AS whole_entry,
> expected_results
> FROM expiration_notify
> GROUP BY url` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_last_text_field_id ON daily_last_text (field_id)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_discrete_text_day ON daily_discrete_text (day)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_counters_field_id ON daily_counters (field_id)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_measurements_provider_id ON measurements (provider_id)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_counters_day ON daily_counters (day)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_discrete_numeric_day ON daily_discrete_numeric (day)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_discrete_numeric_field_id ON daily_discrete_numeric (field_id)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_discrete_text_field_id ON daily_discrete_text (field_id)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_last_numeric_day ON daily_last_numeric (day)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_last_text_day ON daily_last_text (day)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_fields_measurement_id ON fields (measurement_id)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_last_numeric_field_id ON daily_last_numeric (field_id)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 77 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_provider_state_provider_id ON provider_state (provider_id)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 77 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `SELECT null, 'place:folder=' || id || '&queryType=1&type=7', title, null, null, null, null, null, dateAdded, lastModified, null, null, null FROM moz_bookmarks WHERE parent = 4 ORDER BY 3 COLLATE NOCASE ASC` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 58 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `SELECT k.keyword FROM moz_bookmarks b JOIN moz_keywords k ON k.place_id = b.fk WHERE b.id = :item_id ORDER BY k.ROWID DESC LIMIT 1` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 54 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX IF NOT EXISTS moz_bm_reindex_temp_index
> ON moz_bm_reindex_temp(parent)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 31 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `SELECT id, visit_date FROM moz_historyvisits WHERE place_id = (SELECT id FROM moz_places WHERE url = :page_url) ORDER BY visit_date DESC ` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 24 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `SELECT index_table.value, index_table.object_data_key, object_data.file_ids, object_data.data FROM index_data AS index_table JOIN object_data ON index_table.object_store_id = object_data.object_store_id AND index_table.object_data_key = object_data.key WHERE index_table.index_id = :id AND index_table.value < :current_key ORDER BY index_table.value DESC, index_table.object_data_key ASC LIMIT 1` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 22 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `SELECT url, guid, MAX(visit_date) AS visit_date,
>                  MAX(IFNULL(MIN(p_id, 1), MIN(v_id, 0))) AS whole_entry,
>                  expected_results
>           FROM expiration_notify
>           GROUP BY url` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
>
> 20 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `SELECT value, object_data_key FROM index_data WHERE index_id = :id AND value < :current_key ORDER BY value DESC, object_data_key ASC LIMIT 1` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110

[1] https://dxr.mozilla.org/mozilla-central/rev/d4f3a8a75577e4af2914a4e899ca2e724f9715c4/storage/mozStoragePrivateHelpers.cpp?offset=200#97-109
[2] https://dxr.mozilla.org/mozilla-central/rev/d4f3a8a75577e4af2914a4e899ca2e724f9715c4/storage/mozStorageAsyncStatementExecution.cpp#323-326
(In reply to Eric Rahm [:erahm] from comment #0)
> In it's current form it doesn't provide much value; printing the sql
> statement's pointer provides no actionable data.

this is wrong, the pointer is associated to the statement through PRLog, everyone using mozStorage can use that to debug.

> We *can* turn on dumping of the actual SQL statement by #defining
> MOZ_STORAGE_SORTWARNING_SQL_DUMP, which is somewhat more useful. I would
> argue that we should not warn at all unless that value is #defined.

That would be far too verbose, it's easy to introduce these warnings and in some cases it's not even fault of the developer. we made it report only the pointer and the link to documentation pointing to prlog for a reason.

> > 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_last_text_field_id ON daily_last_text (field_id)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110

Strange that CREATE index can issue this warning, it may be a Sqlite bug...

There's no easy way out of this, someone must take the statements one by one and check if it's an effective unoptimized query or a false alarm, and mark statements that cannot be optimized with /* do not warn (bug xxx): reason */
(In reply to Marco Bonardo [::mak] (spotty available until 24 Aug) from comment #1)
> (In reply to Eric Rahm [:erahm] from comment #0)
> > In it's current form it doesn't provide much value; printing the sql
> > statement's pointer provides no actionable data.
> 
> this is wrong, the pointer is associated to the statement through PRLog,
> everyone using mozStorage can use that to debug.

I see, so if you opt into logging this becomes useful. It sounds like a better solution is to switch this message to MOZ_LOG and remove the ifdef.

> > We *can* turn on dumping of the actual SQL statement by #defining
> > MOZ_STORAGE_SORTWARNING_SQL_DUMP, which is somewhat more useful. I would
> > argue that we should not warn at all unless that value is #defined.
> 
> That would be far too verbose, it's easy to introduce these warnings and in
> some cases it's not even fault of the developer. we made it report only the
> pointer and the link to documentation pointing to prlog for a reason.

It's already far too verbose, I don't think it would hurt if it's even more verbose as long as it requires opt-in (so enabling a logger). 

Also note that the documentation [1] does not mention prlog.

[1] http://mzl.la/1FuID0j
(In reply to Marco Bonardo [::mak] (spotty available until 24 Aug) from comment #1)
> > > 96 - [NNNNN] WARNING: Suboptimal indexes for the SQL statement `CREATE INDEX i_daily_last_text_field_id ON daily_last_text (field_id)` [1 sort operation(s)] (http://mzl.la/1FuID0j).: file storage/mozStoragePrivateHelpers.cpp, line 110
> 
> Strange that CREATE index can issue this warning, it may be a Sqlite bug...

Richard, do you know if anything changed in the recent SQLite release that might cause this? Note: it's also possible it's been an issue for a while.

We have code that detects if a sort operation was performed during a query [1] and it's triggering during a |CREATE index| statement. Is this a bug, or is there a way to avoid it?

[1] https://dxr.mozilla.org/mozilla-central/rev/d4f3a8a75577e4af2914a4e899ca2e724f9715c4/storage/mozStoragePrivateHelpers.cpp?offset=300#82-110
Flags: needinfo?(drh)
Creating an index on a (non-empty) table always involves a sort.  That isn't a bug.  In the case of SQLite, the sort associated with a CREATE INDEX is highly optimized and is quite fast, but it is still a sort.

Nothing has recently changed regarding SQLite's use or reporting of sorting in CREATE INDEX.

I suggest something like this:

diff -r cdf53a4dee21 storage/mozStoragePrivateHelpers.cpp
--- a/storage/mozStoragePrivateHelpers.cpp	Thu Aug 13 11:00:54 2015 -0400
+++ b/storage/mozStoragePrivateHelpers.cpp	Thu Aug 13 15:08:54 2015 -0400
@@ -94,6 +94,11 @@
   if (::strstr(sql, "/* do not warn (bug "))
     return;
 
+  // CREATE INDEX always sorts.  (Sorting is a necessary step in creating
+  // and index.)  So ignore the warning there.
+  if (::strstr(sql, "CREATE INDEX"))
+    return;
+
   nsAutoCString message("Suboptimal indexes for the SQL statement ");
 #ifdef MOZ_STORAGE_SORTWARNING_SQL_DUMP
   message.Append('`');
Flags: needinfo?(drh)
(In reply to Eric Rahm [:erahm] from comment #2) 
> I see, so if you opt into logging this becomes useful. It sounds like a
> better solution is to switch this message to MOZ_LOG and remove the ifdef.

The idea is that if you use Storage you (should) have PRLog set to mozStorage:5. when you see one of these warnings in code you recently added/modified, you can open the log and check what it is, and fix it.
Without warnings there's some risk devs won't take care of checking the notifications in the log.

> It's already far too verbose, I don't think it would hurt if it's even more
> verbose as long as it requires opt-in (so enabling a logger). 

yes, maybe we should make it only warn when the logger is enabled, now that storage users are somehow limited, and we could document better the thing in the main mozStorage page on mdn.
We were scared that nobody would have really cared about fixing broken statements if we didn't give them a compelling reason to, the warning was such a "reason".
Showing the statements would hurt, cause some statements are very very long and can fill up a whole shell screen. When we originally enabled them, they stuck for few days before the complains were so loud we had to revert to the pointer.

> Also note that the documentation [1] does not mention prlog.
> 
> [1] http://mzl.la/1FuID0j

oops :/
it should be updated.

(In reply to D. Richard Hipp from comment #4)
> Creating an index on a (non-empty) table always involves a sort.  That isn't
> a bug.  In the case of SQLite, the sort associated with a CREATE INDEX is
> highly optimized and is quite fast, but it is still a sort.

OK, sounds like we should indeed add some filtering on our side, as you suggested.
Thank you.
(In reply to Marco Bonardo [::mak] (spotty available until 24 Aug) from comment #5)
> yes, maybe we should make it only warn when the logger is enabled

or also if MOZ_STORAGE_SORTWARNING_SQL_DUMP is set.
This is simply the patch recommended by Richard. It should cut down warnings by about 1300.
Attachment #8666257 - Flags: review?(mak77)
Assignee: nobody → erahm
Status: NEW → ASSIGNED
Depends on: 1208666
We now only check for sort operations if mozStorage logging is enabled or if MOZ_STORAGE_SORTWARNING_SQL_DUMP is set. Note: I filed bug 1208666 for the two most prominent warnings.
Attachment #8666277 - Flags: review?(mak77)
Comment on attachment 8666257 [details] [diff] [review]
Part 1: Filter out warnings about sort operations on CREATE INDEX statements

Review of attachment 8666257 [details] [diff] [review]:
-----------------------------------------------------------------

::: storage/mozStoragePrivateHelpers.cpp
@@ +94,5 @@
>    if (::strstr(sql, "/* do not warn (bug "))
>      return;
>  
> +  // CREATE INDEX always sorts.  (Sorting is a necessary step in creating
> +  // and index.)  So ignore the warning there.

typo: s/and/an/
Also please move the period after the parenthesis.

@@ +96,5 @@
>  
> +  // CREATE INDEX always sorts.  (Sorting is a necessary step in creating
> +  // and index.)  So ignore the warning there.
> +  if (::strstr(sql, "CREATE INDEX"))
> +    return;

you should also catch "CREATE UNIQUE INDEX" here
Attachment #8666257 - Flags: review?(mak77) → review+
Comment on attachment 8666277 [details] [diff] [review]
Part 2: Only check for sort operations if mozStorage logging is enabled

Review of attachment 8666277 [details] [diff] [review]:
-----------------------------------------------------------------

::: storage/mozStorageAsyncStatementExecution.cpp
@@ +320,5 @@
>      }
>    } while (hasResults);
>  
> +#ifndef MOZ_STORAGE_SORTWARNING_SQL_DUMP
> +  if (MOZ_LOG_TEST(gStorageLog, LogLevel::Debug))

I think Debug is too strict.
We want this to be noticed for most mozStorage logging levels. Warning level should do.
Attachment #8666277 - Flags: review?(mak77) → review+
(In reply to Marco Bonardo [::mak] from comment #9)
> Comment on attachment 8666257 [details] [diff] [review]
> Part 1: Filter out warnings about sort operations on CREATE INDEX statements
> 
> Review of attachment 8666257 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: storage/mozStoragePrivateHelpers.cpp
> @@ +94,5 @@
> >    if (::strstr(sql, "/* do not warn (bug "))
> >      return;
> >  
> > +  // CREATE INDEX always sorts.  (Sorting is a necessary step in creating
> > +  // and index.)  So ignore the warning there.
> 
> typo: s/and/an/
> Also please move the period after the parenthesis.
> 
> @@ +96,5 @@
> >  
> > +  // CREATE INDEX always sorts.  (Sorting is a necessary step in creating
> > +  // and index.)  So ignore the warning there.
> > +  if (::strstr(sql, "CREATE INDEX"))
> > +    return;
> 
> you should also catch "CREATE UNIQUE INDEX" here

I will update the comment and include create unique as well.
(In reply to Marco Bonardo [::mak] from comment #10)
> Comment on attachment 8666277 [details] [diff] [review]
> Part 2: Only check for sort operations if mozStorage logging is enabled
> 
> Review of attachment 8666277 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: storage/mozStorageAsyncStatementExecution.cpp
> @@ +320,5 @@
> >      }
> >    } while (hasResults);
> >  
> > +#ifndef MOZ_STORAGE_SORTWARNING_SQL_DUMP
> > +  if (MOZ_LOG_TEST(gStorageLog, LogLevel::Debug))
> 
> I think Debug is too strict.
> We want this to be noticed for most mozStorage logging levels. Warning level
> should do.

I will set the level to Warning.
https://hg.mozilla.org/integration/mozilla-inbound/rev/5ecfe1c78e636cd12fe68115917b5a5aeb256a88
Bug 1194023 - Part 1: Filter out warnings about sort operations on CREATE INDEX statements. r=mak

https://hg.mozilla.org/integration/mozilla-inbound/rev/9009233203a765d35131df7da70bc7373eb2c9f1
Bug 1194023 - Part 2: Only check for sort operations if mozStorage logging is enabled. r=mak
https://hg.mozilla.org/mozilla-central/rev/5ecfe1c78e63
https://hg.mozilla.org/mozilla-central/rev/9009233203a7
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla44
You need to log in before you can comment on or make changes to this bug.