Closed
Bug 963554
Opened 10 years ago
Closed 10 years ago
Adding the original SQL statement to the WARNING about sort operations in TB (C-C).
Categories
(Toolkit :: Storage, enhancement)
Toolkit
Storage
Tracking
()
RESOLVED
FIXED
mozilla32
People
(Reporter: ishikawa, Assigned: ishikawa)
Details
Attachments
(1 file, 4 obsolete files)
1.36 KB,
patch
|
ishikawa
:
review+
|
Details | Diff | Splinter Review |
I am tryint go clean up voluminous the verbose WARNING lines in the logging output of |make mozmill| test suite run of DEBUG BUILD of TB. See for example: Bug 963550 - Issue WARNING messages about missing OpenGL support ONLY ONCE during the execution. Bug 963544 - Removing (DEBUG BUILD) WARNING messages from a few NS_ENSURE_TRUE() in dom/base//Navigator.cpp Here, I am proposing to add an additional information to a warning message. This additional information may be available by setting environment variable but I think it is worth hile to add this directly to the WARNING line printed by DEBUG BUILD of TB. The case in point. The DEBUG BUILD of TB issues the warning about the number of sort operations that have occurred for a SQL statement. However, the SQL statement itself, which caused the sort operation, is not printed. I am proposing a patch to ADD the original SQL statement that caused the sort operation to happen in the first place to the warning message. Currently, the original SQL statement is not available then and there, and so the warning in the output of DEBUG OUTPUT of TB is not immediately useful. [I suspect that it can be printed by setting an environment variable, but why not add that missing information *IF* it was deemed worthwhile to report about the sort operation after all in DEBUG BUILD TB binary.] BTW, note, the shown source file and line number that is printed by NS_WARNING() is that of the print routine itself and NOT where the original SQL statement comes from (in javascript?). I have not touched that issue here. I suppose adding the filename [and line number] as a trailing comment to the SQL statement when it is issued may be a way to go. There are other places where such warning is printed by a helper function and the helper function's filename and line is printed together with the warning messages. These ought to carry the filename and line number of the ORIGINAL place where the reported event happened. In C/C++, __FILENAME__ and __LINE__ can be stringfied and concatenated and passed to the helper function. But I digress. TIA
Assignee | ||
Updated•10 years ago
|
Attachment #8365063 -
Flags: review?(mozilla)
Comment 1•10 years ago
|
||
Comment on attachment 8365063 [details] [diff] [review] A patch to dump the original SQL statement that caused sort operation(s) in the WARNING message. bienvenu isn't really reviewing much these days, but anyhow he's not a reviewer for this code
Attachment #8365063 -
Flags: review?(mozilla) → review?(mak77)
Updated•10 years ago
|
Assignee: nobody → ishikawa
Comment 2•10 years ago
|
||
Comment on attachment 8365063 [details] [diff] [review] A patch to dump the original SQL statement that caused sort operation(s) in the WARNING message. Review of attachment 8365063 [details] [diff] [review]: ----------------------------------------------------------------- I'm sorry but this is exactly how it was originally, a lot of developers started to complain that it was creating too much spam in the console, so it was decided to only print out the address of the statement and let devs interested into debugging them use nsprlog to match address to statement. Since there's nothing new here to avoid annoying other developers, this is sadly a r-. If it may be useful to you, maybe we could evaluate adding a define to print out the SQL, then you could enable that and get a build that prints all SQL instead of addresses.
Attachment #8365063 -
Flags: review?(mak77) → review-
Assignee | ||
Comment 3•10 years ago
|
||
(In reply to Marco Bonardo [:mak] from comment #2) > Comment on attachment 8365063 [details] [diff] [review] > A patch to dump the original SQL statement that caused sort operation(s) in > the WARNING message. > > Review of attachment 8365063 [details] [diff] [review]: > ----------------------------------------------------------------- > > I'm sorry but this is exactly how it was originally, a lot of developers > started to complain that it was creating too much spam in the console, so it > was decided to only print out the address of the statement and let devs > interested into debugging them use nsprlog to match address to statement. > > Since there's nothing new here to avoid annoying other developers, this is > sadly a r-. If it may be useful to you, maybe we could evaluate adding a > define to print out the SQL, then you could enable that and get a build that > prints all SQL instead of addresses. Thank you for the information on the history. However, I would like to raise an issue here before I decide to give up. Let me play the devil's advocate. I need to have some fun. People complained as spams? Lots of spams? This is for ordinary compilation or DEBUG BUILD (with -DDEBUG=1)? I assume this is about DEBUG BUILD since that lines are printed within #if DEBUG section. Let us look at the numbers. |make mozmill| test suite run of DEBUG BUILD of TB produce about 73K+ lines (including large amount of test administrative output). It runs about 1000+ tests from 35+ directories (I had to say 35+ here since under my local PC configuration, somehow tests under a directory often fail due to network issues(?).) The log is about 6+MB on my PC. Among this voluminous output of 73K+ lines, guess how often this "sort operation ..." warning is printed? People complained of spamming. Dozens, or hundreds? grep "sort operation" log356-mozmill.txt | wc 6 114 1488 Yeah, right. SIX (6) lines in total. So we are spammed, all right. (log356-mozmill.txt was produced about 10 days ago.) In the meantime, there were other warning lines that get printed. Say, an irritating OpenGL warnings of the following form: [27035] WARNING: OpenGL-accelerated layers are not supported on this system: file /REF-COMM-CENTRAL/comm-central/mozilla/widget/xpwidgets/nsBaseWidget.cpp, line 898 This was made less frequent by the patch in Bug 963550 - Issue WARNING messages about missing OpenGL support ONLY ONCE during the execution. Before the reduction, though, how many OpenGL warning lines were there? If six lines are spam, then several, or dozens? grep -i opengl log356-mozmill.txt | wc 558 7812 92628 OK more than five hundred lines. (After the patch it was reduced to 35.) There were also warning lines that were produced and are removed by the patch in the following: Bug 963544 - Removing (DEBUG BUILD) WARNING messages from a few NS_ENSURE_TRUE() in dom/base//Navigator.cpp The form of the warning is like the following (there were three such warnings coming from three different locations): [31444] WARNING: NS_ENSURE_TRUE(enabled) failed: file /REF-COMM-CENTRAL/comm-central/mozilla/dom/base/Navigator.cpp, line 1869 Before the elimination, there were a lot of them. How many ? Dozens, or hundreds? grep "NS_ENSURE_TRUE(enabled) failed: file /REF-COMM-CENTRAL/comm-central/mozilla/dom/base/Navigator.cpp" log356-mozmill.txt | wc 1344 10752 172032 Yeah, right. More than 1300 lines without giving us much value. THAT is worth calling a spam. So as far as the CURRENT real numbers are concerned, the lines printed discussed here for SQL is miniscule. A drop in the bucket. Maybe the situation was different when this was decided years ago(?). Any chance of re-thinking? I think it is stupid not to show the problematic command lines if it is so important for performance evaluation and mentions about it in the DEBUG BUILD output in the first place, and not showing the SQL command line itself. What do people think? Oh, BTW, I have another WARNING line that I want to eliminate from DEBUG BUILD. That is [27035] WARNING: NS_ENSURE_TRUE(globalObject && globalObject->GetGlobalJSObject()) failed: file /REF-COMM-CENTRAL/comm-central/mozilla/content/html/document/src/nsHTMLContentSink.cpp, line 717 Guess how many such lines are in |make mozmill| log? Dozens, hundreds? grep "WARNING: NS_ENSURE_TRUE(globalObject && globalObject->GetGlobalJSObject()) failed" log356-mozmill.txt | wc 879 8790 170526 Hmm, 900-. Not bad for vying for the most frequent spamming line. (not that I know this is the most frequent single warning at this moment. Finding that needs writing a fairly complicated script. After eliminating backtrace, and other testing output, there are about 3.4K lines and so 879 is fairly a large chunk of that remaining lines, though.) If mozilla developer community still thinks, after all these numbers, this added output of SQL command line is spamming their DEBUG BUILD output, their idea of priority seems to me severely broken. TIA PS: I just want to make sure that people are NOT MIXING this valid performance warning with the SHUTDOWN SEQUENCE problem that leave some SQL commands not finalized and thus warning lines for EACH pending SQL command that are not finalized (committed?) to be printed. These warnings get printed at the end of, say, shutdown time of DEBUG BUILD of TB or FF, and indeed may add up to several long SQL command lines. But IMHO, these are NOT spams, only as a result of SERIOUS SHUTDOWN ERROR, still not fixed after so many years. Someone familiar with the shutdown issue ought to fix it RSN. Or mentor someone who can work on such issues. PPS: The SQL command in the patch gets printed ONLY when they do not use index. I suspect many SQL commands do use index and so never get printed (except for when they are not finalized due to the shutdown issue noted below.) PPPS: some may say, OK, 6 lines, but if these six lines appear in a chunk for a session, that is still distracting. All other warnings I mentioned are spread over many test (which is not actually so true in the case of the last one (879 occurrences: there are many back-to-back occurrences of three such warnings). Just look at the log of |make mozmill| of DEBUG BUILD of TB. (I think tryserver is your friend.) In my local log above, "sort operation" warning come in a pair of back-to-back two lines in three different tests. Hardly a spam at all IMHO. PPPPS: I don't know much about how often TB's test output is "spammed". But let us have the numbers for an effective discussion like the above to convince me that the lines are spam.
Assignee | ||
Comment 4•10 years ago
|
||
>PPPPS: I don't know much about how often TB's test output is "spammed".
I meant to refer to FF's test.
TIA
Assignee | ||
Comment 5•10 years ago
|
||
Minor nit: I miscalculated.
There were about 10K WARNING lines (10355) in the log.
The number I refered above "3.4K lines" is the remaining lines after "WARNING" lines were also removed
along with other test-specific administrative output.
>grep "WARNING: NS_ENSURE_TRUE(globalObject && globalObject->GetGlobalJSObject()) failed" log356-mozmill.txt | wc
> 879 8790 170526
879 lines among them is still a large portion.
That "sort operation" is not spamming the output IMHO still stands.
TIA
Comment 6•10 years ago
|
||
I can understand your concerns, and I surely sympathize with them, though it's not making the warnings-spam situation worse, that we are going to improve it. If any module would just say "we generate just 10 warnings out of thousands", those thousands would never reduce. It's not just a few warning lines on Thunderbird, this is a global change that may cause tens of these warnings on the other projects using Storage. Yes, the situation *may* be better than it was years ago, due to us properly annotating queries with "DO NOT WARN" comments, and converting some consumers from Sqlite to json or other storage types. But we also have new consumers like indexedDB that could make things noisy due to their abstract nature. And it's not just matter of using indices, in some cases you just can't use an index (generated values) or Sqlite decides that it's not worth to use an index, cause there are so few results that a table scan is faster. So, you can get warnings without expecting them, and even be unable to do anything about them, apart marking the SQL with /* do not warn (bug 123456) */). This also adds burden on module owners to assign people to those bugs soon, to shut up the warn (some queries are very long and indeed annoying). With the exact count of the current warnings on a mozilla-central complete testrun, we could at least make a guess on future maintenance costs, otherwise I can only refer to the de-facto situation (that was already approved by the module owner and release drivers in 2009) and suggest to add a separate define to get a build with inline SQL.
Assignee | ||
Comment 7•10 years ago
|
||
(In reply to Marco Bonardo [:mak] from comment #6) > I can understand your concerns, and I surely sympathize with them, though > it's not making the warnings-spam situation worse, that we are going to > improve it. If any module would just say "we generate just 10 warnings out > of thousands", those thousands would never reduce. Thank you for your review. Your points are well taken. > It's not just a few warning lines on Thunderbird, this is a global change > that may cause tens of these warnings on the other projects using Storage. > Yes, the situation *may* be better than it was years ago, due to us properly > annotating queries with "DO NOT WARN" comments, and converting some > consumers from Sqlite to json or other storage types. But we also have new > consumers like indexedDB that could make things noisy due to their abstract > nature. > > And it's not just matter of using indices, in some cases you just can't use > an index (generated values) or Sqlite decides that it's not worth to use an > index, cause there are so few results that a table scan is faster. So, you > can get warnings without expecting them, and even be unable to do anything > about them, apart marking the SQL with /* do not warn (bug 123456) */). This > also adds burden on module owners to assign people to those bugs soon, to > shut up the warn (some queries are very long and indeed annoying). I have not realized this dynamic behavior of storage backend. But now I realize it after your explanation AND the really different SQL statements that get printed in the log (!) :-) > With the exact count of the current warnings on a mozilla-central complete > testrun, we could at least make a guess on future maintenance costs, > otherwise I can only refer to the de-facto situation (that was already > approved by the module owner and release drivers in 2009) and suggest to add > a separate define to get a build with inline SQL. OK, so I am uploading a patch that does just that. What do you and others think? TIA
Assignee | ||
Updated•10 years ago
|
Attachment #8367931 -
Flags: review?(mak77)
Comment 8•10 years ago
|
||
Comment on attachment 8367931 [details] [diff] [review] patch (take 2) Review of attachment 8367931 [details] [diff] [review]: ----------------------------------------------------------------- ::: storage/src/mozStoragePrivateHelpers.cpp @@ +101,5 @@ > message.Append(" sort operation has "); > else > message.Append(" sort operations have "); > message.Append("occurred for the SQL statement '"); > nsPrintfCString address("0x%p", aStatement); The only purpose of the address here was to match up with nsPRLOG, so I think you may just do this: message.Append("occurred for the SQL statement '"); #ifdef MOZ_STORAGE_SORTWARNING_SQL_DUMP message.Append(sql); #else nsPrintfCString address("0x%p", aStatement); message.Append(address); #endif message.Append("'. See https://developer.mozilla.... @@ +105,5 @@ > nsPrintfCString address("0x%p", aStatement); > message.Append(address); > message.Append("'. See https://developer.mozilla.org/En/Storage/Warnings " > "details."); > +#if DEBUG_sql_dump please use MOZ_STORAGE_SORTWARNING_SQL_DUMP @@ +108,5 @@ > "details."); > +#if DEBUG_sql_dump > + message.Append("\n SQL command: "); > + message.Append(sql); > +#endif see above.
Attachment #8367931 -
Flags: review?(mak77) → feedback+
Assignee | ||
Comment 9•10 years ago
|
||
Sorry, I could not follow this up for a couple of months. Now I will work on the patch to produce a new patch to reflect the comment in comment 8, hopefully before next week. TIA
Assignee | ||
Updated•10 years ago
|
Component: Untriaged → SQL
Product: Thunderbird → Core
QA Contact: owen.marshall+bmo
Assignee | ||
Comment 10•10 years ago
|
||
(In reply to ISHIKAWA, Chiaki from comment #9) > Sorry, I could not follow this up for a couple of months. Now I will work on > the patch to produce > a new patch to reflect the comment in comment 8, hopefully before next week. > > TIA Here is the updated patch. Compiled locally. TIA PS: I also changed the component reassigned to core:sql.
Attachment #8409423 -
Flags: review?(mak77)
Assignee | ||
Updated•10 years ago
|
Attachment #8367931 -
Attachment is obsolete: true
Updated•10 years ago
|
Component: SQL → Storage
Product: Core → Toolkit
Comment 11•10 years ago
|
||
core/SQL is just legacy component, I'm not even sure what we use it for nowadays, probably nothing.
Comment 12•10 years ago
|
||
Comment on attachment 8409423 [details] [diff] [review] Final Patch Review of attachment 8409423 [details] [diff] [review]: ----------------------------------------------------------------- ::: storage/src/mozStoragePrivateHelpers.cpp @@ +112,5 @@ > "details."); > +#if MOZ_STORAGE_SORTWARNING_SQL_DUMP > + message.Append("\n SQL command: "); > + message.Append(sql); > +#endif We should not be appending the sql text twice, we are already inlining it above. Please just remove these 4 lines. Sorry if I was unclear about that.
Attachment #8409423 -
Flags: review?(mak77) → review+
Assignee | ||
Comment 13•10 years ago
|
||
(In reply to Marco Bonardo [:mak] from comment #12) > Comment on attachment 8409423 [details] [diff] [review] > Final Patch > > Review of attachment 8409423 [details] [diff] [review]: > ----------------------------------------------------------------- > > ::: storage/src/mozStoragePrivateHelpers.cpp > @@ +112,5 @@ > > "details."); > > +#if MOZ_STORAGE_SORTWARNING_SQL_DUMP > > + message.Append("\n SQL command: "); > > + message.Append(sql); > > +#endif > > We should not be appending the sql text twice, we are already inlining it > above. Please just remove these 4 lines. Sorry if I was unclear about that. No, it was my fault: I was away from this code for so long and not read the comment carefully. Please find the modified patch, but I am carrying over the review+ for now. If there is no objection, I will set checkin-needed keyword on Saturday possibly. TIA
Attachment #8365063 -
Attachment is obsolete: true
Attachment #8409423 -
Attachment is obsolete: true
Attachment #8411664 -
Flags: review+
Comment 14•10 years ago
|
||
Comment on attachment 8411664 [details] [diff] [review] Really final patch (take 2) carrying over mak77:review+ Review of attachment 8411664 [details] [diff] [review]: ----------------------------------------------------------------- ::: storage/src/mozStoragePrivateHelpers.cpp @@ +102,5 @@ > else > message.Append(" sort operations have "); > message.Append("occurred for the SQL statement '"); > +#ifdef MOZ_STORAGE_SORTWARNING_SQL_DUMP > + message.Append("\n SQL command: "); I'd probably also omit this row, so that we just print ... for the SQL statement 'SELECT ...'. See https://... in one case and ... for the SQL statement '0x123...'. See https://... in the other case but I don't care that much, if it helps your readability, no problem.
Assignee | ||
Comment 15•10 years ago
|
||
(In reply to Marco Bonardo [:mak] from comment #14) > Comment on attachment 8411664 [details] [diff] [review] > Really final patch (take 2) carrying over mak77:review+ > > Review of attachment 8411664 [details] [diff] [review]: > ----------------------------------------------------------------- > > ::: storage/src/mozStoragePrivateHelpers.cpp > @@ +102,5 @@ > > else > > message.Append(" sort operations have "); > > message.Append("occurred for the SQL statement '"); > > +#ifdef MOZ_STORAGE_SORTWARNING_SQL_DUMP > > + message.Append("\n SQL command: "); > > I'd probably also omit this row, so that we just print > > ... for the SQL statement 'SELECT ...'. See https://... > in one case and > ... for the SQL statement '0x123...'. See https://... > in the other case > > but I don't care that much, if it helps your readability, no problem. Thank you for the comment. Actually, creating summary with scripts is easier without "\n". So I removed '\n' so that the dump appears as a long one one. I am uploading the patch with this change, and will put checkin-needed comment. Thank you again.
Attachment #8414180 -
Flags: review+
Assignee | ||
Updated•10 years ago
|
Keywords: checkin-needed
Assignee | ||
Updated•10 years ago
|
Attachment #8411664 -
Attachment is obsolete: true
Comment 16•10 years ago
|
||
https://hg.mozilla.org/integration/fx-team/rev/5ed3fa857eac
Keywords: checkin-needed
Whiteboard: [fixed-in-fx-team]
Comment 17•10 years ago
|
||
https://hg.mozilla.org/mozilla-central/rev/5ed3fa857eac
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → mozilla32
You need to log in
before you can comment on or make changes to this bug.
Description
•