You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "Riley Patterson (JIRA)" <ji...@apache.org> on 2011/07/19 23:58:58 UTC
[jira] [Created] (HBASE-4117) Slow Query Log
Slow Query Log
--------------
Key: HBASE-4117
URL: https://issues.apache.org/jira/browse/HBASE-4117
Project: HBase
Issue Type: New Feature
Components: ipc
Reporter: Riley Patterson
Assignee: Riley Patterson
Priority: Minor
Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "stack (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13085998#comment-13085998 ]
stack commented on HBASE-4117:
------------------------------
Thanks Riley.
Over in hbase-880 when we were talking refactoring, base class there was Operation -- e.g. https://issues.apache.org/jira/secure/attachment/12391309/NewCilentAPIProposoal4.gif -- in a few proposals and RowOperation in others. You already have a Row interface, so maybe Operation is ok... (I don't see row specifics going on in your Operation instance currently). Good stuff.
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (HBASE-4117) Slow Query Log
Posted by "Riley Patterson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Riley Patterson updated HBASE-4117:
-----------------------------------
Attachment: HBASE-4117-v3.patch
Small code-cleanup changes.
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117-v2.patch, HBASE-4117-v3.patch, HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "stack (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13085855#comment-13085855 ]
stack commented on HBASE-4117:
------------------------------
How is jettison related to jackson, the json lib we use elsewhere in hbase? It throws events as it trips over the json. Can jackson do this?
The clause under 'if (processingTime > warnResponseTime) {' could be broken out into a method?
Should the above test include if logging is DEBUG or more or is thought that this slow logging will be always on?
You don't want to log something here:
{code}
+ } catch (JSONException e) {
+ // ignore
+ }
{code}
Could be confusing if I'm expecting logging and its not coming out -- would appreciate the failure being logged. There is another instance later in this code block.
Would 'Operation' be better than 'DatabaseCommand'? Currently this superclass factors into a superclass various kinds of representations of hbase operations -- tostring, fingerprint as map, json -- etc. Thats fine for now. It could do more with time.
I like this getFingerprint.
getDetails seems too generic a name for the method. If you are going to go generic, toMap to go with toString might be better? (Oh, nvm, I see you went one better and made the toString member of the superclass -- good).
Are you removing toString from Delete? Thats probably not good. The toString could use your fingerprinting.
Shouldn't the methods in Row be added to your new base class? Row Interface should only have 'row' things in it, not getDetails and getFamilyMap.
A couple of tests would be good where you do some toStringing and toJSON'ing and verify its doing right thing.
Nice patch Riley. Nice functionality.
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (HBASE-4117) Slow Query Log
Posted by "Riley Patterson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Riley Patterson updated HBASE-4117:
-----------------------------------
Labels: client ipc (was: )
Release Note:
Exposes JSON-parseable fingerprint and details for queries that take longer than a configurable threshold time. The exposure is currently to the main regionserver log, along with a (queryTooSlow) tag which allows it to be grepped out and easily aggregated and/or monitored in adminstrator scripts.
The patch also provides a standard way to extract fingerprint and detail information of interest by requiring each "DatabaseCommand" to provide a fingerprint map and a details map, which will be a superset of the fingerprint.
Status: Patch Available (was: Open)
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: ipc, client
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (HBASE-4117) Slow Query Log
Posted by "Riley Patterson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Riley Patterson updated HBASE-4117:
-----------------------------------
Attachment: HBASE-4117-doc.txt
A basic, user-manual type of document describing the feature, its use, its configuration, and grokking its output.
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Fix For: 0.92.0
>
> Attachments: HBASE-4117-doc.txt, HBASE-4117-v2.patch, HBASE-4117-v3.patch, HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "jiraposter@reviews.apache.org (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13089146#comment-13089146 ]
jiraposter@reviews.apache.org commented on HBASE-4117:
------------------------------------------------------
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/1621/
-----------------------------------------------------------
(Updated 2011-08-22 23:25:12.626245)
Review request for hbase.
Changes
-------
Addressed stack's comments from last week, cleaned up code, standardized many fields in the JSON output.
Summary
-------
Exposes JSON-parseable fingerprint and details for queries that take longer than a configurable threshold time. The exposure is currently to the main regionserver log, along with a (operationTooSlow) tag which allows it to be grepped out and easily aggregated and/or monitored in administrator scripts.
The patch also provides a standard way to extract fingerprint and detail information of interest by requiring each "Operation" to provide a fingerprint map and a details map, which will be a superset of the fingerprint.
This addresses bug HBASE-4117.
https://issues.apache.org/jira/browse/HBASE-4117
Diffs
-----
/src/main/java/org/apache/hadoop/hbase/KeyValue.java 1160468
/src/main/java/org/apache/hadoop/hbase/client/Delete.java 1160468
/src/main/java/org/apache/hadoop/hbase/client/Get.java 1160468
/src/main/java/org/apache/hadoop/hbase/client/MultiAction.java 1160468
/src/main/java/org/apache/hadoop/hbase/client/MultiPut.java 1160468
/src/main/java/org/apache/hadoop/hbase/client/Operation.java PRE-CREATION
/src/main/java/org/apache/hadoop/hbase/client/Put.java 1160468
/src/main/java/org/apache/hadoop/hbase/client/Scan.java 1160468
/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java 1160468
/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java 1160468
/src/test/java/org/apache/hadoop/hbase/client/TestOperation.java PRE-CREATION
Diff: https://reviews.apache.org/r/1621/diff
Testing
-------
Monitored get and put latency with and without the patch using reasonable hbase.ipc.warn.response.time settings (1000ms, 2000ms). Performance was not noticeably impacted.
Thanks,
Riley
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "Hudson (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13191882#comment-13191882 ]
Hudson commented on HBASE-4117:
-------------------------------
Integrated in HBase-TRUNK #2645 (See [https://builds.apache.org/job/HBase-TRUNK/2645/])
Add Riley's slow query doc from hbase-4117
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Fix For: 0.92.0
>
> Attachments: HBASE-4117-doc.txt, HBASE-4117-v2.patch, HBASE-4117-v3.patch, HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Resolved] (HBASE-4117) Slow Query Log
Posted by "stack (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
stack resolved HBASE-4117.
--------------------------
Resolution: Fixed
Fix Version/s: 0.92.0
Hadoop Flags: [Reviewed]
Nice one Riley. Committed to TRUNK (For future, be careful on the white space.. I cleaned it up before commit).
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Fix For: 0.92.0
>
> Attachments: HBASE-4117-v2.patch, HBASE-4117-v3.patch, HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "Hudson (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13191939#comment-13191939 ]
Hudson commented on HBASE-4117:
-------------------------------
Integrated in HBase-TRUNK-security #86 (See [https://builds.apache.org/job/HBase-TRUNK-security/86/])
Add Riley's slow query doc from hbase-4117
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Fix For: 0.92.0
>
> Attachments: HBASE-4117-doc.txt, HBASE-4117-v2.patch, HBASE-4117-v3.patch, HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "Andrew Purtell (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13086071#comment-13086071 ]
Andrew Purtell commented on HBASE-4117:
---------------------------------------
bq. This information resides in the TaskMonitor singleton, which can then be exposed any way you like. I think this design makes a lot of sense; historical information goes in the main log, while current status information can be queried from a clean interface and exposed any way you like.
Fair enough. I stand corrected / mollified.
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (HBASE-4117) Slow Query Log
Posted by "Riley Patterson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Riley Patterson updated HBASE-4117:
-----------------------------------
Status: Open (was: Patch Available)
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (HBASE-4117) Slow Query Log
Posted by "Riley Patterson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Riley Patterson updated HBASE-4117:
-----------------------------------
Attachment: HBASE-4117-v2.patch
Addressed many of the comments and suggestions from this thread.
Also posted on: https://reviews.apache.org/r/1621/
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117-v2.patch, HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "Ted Yu (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13085710#comment-13085710 ]
Ted Yu commented on HBASE-4117:
-------------------------------
Please combine javadoc in one line:
{code}
+ /** Default value for above param */
+ private static final int DEFAULT_WARN_RESPONSE_TIME = 1000; // milliseconds
{code}
{code}
+public abstract class DatabaseCommand {
{code}
Maybe we can find a better name for the above class whose purpose is for logging and debugging ?
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (HBASE-4117) Slow Query Log
Posted by "Riley Patterson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Riley Patterson updated HBASE-4117:
-----------------------------------
Attachment: HBASE-4117.patch
Exposes JSON-parseable fingerprint and details for queries that take longer than a configurable threshold time. The exposure is currently to the main regionserver log, along with a (queryTooSlow) tag which allows it to be grepped out and easily aggregated and/or monitored in adminstrator scripts.
The patch also provides a standard way to extract fingerprint and detail information of interest by requiring each "DatabaseCommand" to provide a fingerprint map and a details map, which will be a superset of the fingerprint.
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "Gary Helmling (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13086082#comment-13086082 ]
Gary Helmling commented on HBASE-4117:
--------------------------------------
Riley, would you mind putting this up on reviews.apache.org? This is a pretty big change to read through as a patch. Thanks!
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "Riley Patterson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13086045#comment-13086045 ]
Riley Patterson commented on HBASE-4117:
----------------------------------------
This isn't really meant to enable gathering of status information. It is a bunch of historical information which is highly related to other information in the main log. Without the context of log events regarding compactions, region reassignments, etc. that we gain by placing it in the main log, we lose most of the utility. It can also provide context to other log events that may have been caused by RPC handlers getting locked up on slow queries.
We could additionally log this information somewhere in a monitor in memory or in its own separate log and open this up to RPC access, but it would duplicate a lot of historical information which would likely see infrequent use. I don't think there's any more reason to do this for this particular feature than for most other events logged in our main log file.
Note that I'm also finishing up work on an initial implementation of HBASE-4057, which deals directly with status information for the calls currently being serviced by RPC handlers and enables exposure of the contents of getFingerprint and getDetails in a more general way. This information resides in the TaskMonitor singleton, which can then be exposed any way you like. I think this design makes a lot of sense; historical information goes in the main log, while current status information can be queried from a clean interface and exposed any way you like.
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "stack (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13086126#comment-13086126 ]
stack commented on HBASE-4117:
------------------------------
@Andrew I appreciate your showing up in your architect hat flashing the red card. Please stay on the prowl and flag the violations.
In this case, on review, I think we are talking honest logging (logging already has a system that facilitates redirection and feeding events to other than files that live under HBASE_LOG_DIR -- which reminds me, I need to go back to Riley and make sure that these events CAN be directed to other than the .log file cleanly). As Riley says, these logs at an extreme will likely make most sense if shown in context amidst the logging of what else was going on on the server.
The patch also includes nice refactoring of base classes -- Scan, Get, etc. -- to make it so they can dump out a self-description (either a fingerprint/synopsis, or a full catalog of the payload being carried) in text or json that looks like it can be passed to whatever asks for the info (log or metrics or...)
We are still missing the general theory on how to pass hbase emissions but I think this patch helps move us closer to a general system much more than it adds distraction.
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "jiraposter@reviews.apache.org (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13092185#comment-13092185 ]
jiraposter@reviews.apache.org commented on HBASE-4117:
------------------------------------------------------
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/1621/#review1669
-----------------------------------------------------------
Ship it!
/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java
<https://reviews.apache.org/r/1621/#comment3771>
Why remove this stuff Riley? Seems useful? Or, looks like you moved it. What you thinking? Move it out of the generic into the specific implementation engine?
/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java
<https://reviews.apache.org/r/1621/#comment3772>
nice
Doing check for both too large and too slow
I suppose this answers my previous question.
- Michael
On 2011-08-26 04:00:49, Riley Patterson wrote:
bq.
bq. -----------------------------------------------------------
bq. This is an automatically generated e-mail. To reply, visit:
bq. https://reviews.apache.org/r/1621/
bq. -----------------------------------------------------------
bq.
bq. (Updated 2011-08-26 04:00:49)
bq.
bq.
bq. Review request for hbase.
bq.
bq.
bq. Summary
bq. -------
bq.
bq. Exposes JSON-parseable fingerprint and details for queries that take longer than a configurable threshold time. The exposure is currently to the main regionserver log, along with a (operationTooSlow) tag which allows it to be grepped out and easily aggregated and/or monitored in administrator scripts.
bq.
bq. The patch also provides a standard way to extract fingerprint and detail information of interest by requiring each "Operation" to provide a fingerprint map and a details map, which will be a superset of the fingerprint.
bq.
bq.
bq. This addresses bug HBASE-4117.
bq. https://issues.apache.org/jira/browse/HBASE-4117
bq.
bq.
bq. Diffs
bq. -----
bq.
bq. /src/main/java/org/apache/hadoop/hbase/KeyValue.java 1161979
bq. /src/main/java/org/apache/hadoop/hbase/client/Delete.java 1161979
bq. /src/main/java/org/apache/hadoop/hbase/client/Get.java 1161979
bq. /src/main/java/org/apache/hadoop/hbase/client/MultiAction.java 1161979
bq. /src/main/java/org/apache/hadoop/hbase/client/MultiPut.java 1161979
bq. /src/main/java/org/apache/hadoop/hbase/client/Operation.java PRE-CREATION
bq. /src/main/java/org/apache/hadoop/hbase/client/Put.java 1161979
bq. /src/main/java/org/apache/hadoop/hbase/client/Scan.java 1161979
bq. /src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java 1161979
bq. /src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java 1161979
bq. /src/test/java/org/apache/hadoop/hbase/client/TestOperation.java PRE-CREATION
bq.
bq. Diff: https://reviews.apache.org/r/1621/diff
bq.
bq.
bq. Testing
bq. -------
bq.
bq. Monitored get and put latency with and without the patch using reasonable hbase.ipc.warn.response.time settings (1000ms, 2000ms). Performance was not noticeably impacted.
bq.
bq.
bq. Thanks,
bq.
bq. Riley
bq.
bq.
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117-v2.patch, HBASE-4117-v3.patch, HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "Andrew Purtell (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13086028#comment-13086028 ]
Andrew Purtell commented on HBASE-4117:
---------------------------------------
I'm not suggesting turning down good work.
However I renew my objection to the result of adding this feature as is. We end up with a hodgepodge of methods for gathering status information or taking administrative action. Do I use the shell? Do I grab some JSON at some path on the server? (And at more than one path?) Do I grep the logs? This is not good design. Why can't this information be made retrievable via the Java admin API via RPC (and therefore the shell can manipulate it)? Why can't we have a common interface that lets us expose this type of information by RPC or by servlet or by logging?
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "jiraposter@reviews.apache.org (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13091556#comment-13091556 ]
jiraposter@reviews.apache.org commented on HBASE-4117:
------------------------------------------------------
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/1621/
-----------------------------------------------------------
(Updated 2011-08-26 04:00:49.869021)
Review request for hbase.
Changes
-------
Several code-cleanup related changes.
Summary
-------
Exposes JSON-parseable fingerprint and details for queries that take longer than a configurable threshold time. The exposure is currently to the main regionserver log, along with a (operationTooSlow) tag which allows it to be grepped out and easily aggregated and/or monitored in administrator scripts.
The patch also provides a standard way to extract fingerprint and detail information of interest by requiring each "Operation" to provide a fingerprint map and a details map, which will be a superset of the fingerprint.
This addresses bug HBASE-4117.
https://issues.apache.org/jira/browse/HBASE-4117
Diffs (updated)
-----
/src/main/java/org/apache/hadoop/hbase/KeyValue.java 1161979
/src/main/java/org/apache/hadoop/hbase/client/Delete.java 1161979
/src/main/java/org/apache/hadoop/hbase/client/Get.java 1161979
/src/main/java/org/apache/hadoop/hbase/client/MultiAction.java 1161979
/src/main/java/org/apache/hadoop/hbase/client/MultiPut.java 1161979
/src/main/java/org/apache/hadoop/hbase/client/Operation.java PRE-CREATION
/src/main/java/org/apache/hadoop/hbase/client/Put.java 1161979
/src/main/java/org/apache/hadoop/hbase/client/Scan.java 1161979
/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java 1161979
/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java 1161979
/src/test/java/org/apache/hadoop/hbase/client/TestOperation.java PRE-CREATION
Diff: https://reviews.apache.org/r/1621/diff
Testing
-------
Monitored get and put latency with and without the patch using reasonable hbase.ipc.warn.response.time settings (1000ms, 2000ms). Performance was not noticeably impacted.
Thanks,
Riley
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117-v2.patch, HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "Riley Patterson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13085990#comment-13085990 ]
Riley Patterson commented on HBASE-4117:
----------------------------------------
Jackson does look like it could be a better choice for JSON encoding; I used jettison for consistency with my HLog Pretty Printer (HBASE-3968). It seems like jackson is more actively maintained, and we should probably be consistent throughout the project, so I'll go ahead and change this patch to use jackson as well as patching the HLog Pretty Printer to also use jackson.
Separating the logging into its own method sounds like a good idea as well. On it.
The slow logging can be turned off by setting hbase.ipc.warn.response.time very large. I could add an additional check for nonnegativity which would make disabling slow logging a bit more intuitive (set to -1). I do think that this feature should be enabled even when DEBUG logging is not, as it could be useful for DBA's as well as core developers.
I'm open for suggestions for the name of the super class. Operation sounds fine.
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Attachments: HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (HBASE-4117) Slow Query Log
Posted by "Hudson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-4117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13092219#comment-13092219 ]
Hudson commented on HBASE-4117:
-------------------------------
Integrated in HBase-TRUNK #2151 (See [https://builds.apache.org/job/HBase-TRUNK/2151/])
HBASE-4117 Slow Query Log and Client Operation Fingerprints
stack :
Files :
* /hbase/trunk/CHANGES.txt
* /hbase/trunk/src/main/java/org/apache/hadoop/hbase/KeyValue.java
* /hbase/trunk/src/main/java/org/apache/hadoop/hbase/client/Delete.java
* /hbase/trunk/src/main/java/org/apache/hadoop/hbase/client/Get.java
* /hbase/trunk/src/main/java/org/apache/hadoop/hbase/client/MultiAction.java
* /hbase/trunk/src/main/java/org/apache/hadoop/hbase/client/MultiPut.java
* /hbase/trunk/src/main/java/org/apache/hadoop/hbase/client/Operation.java
* /hbase/trunk/src/main/java/org/apache/hadoop/hbase/client/Put.java
* /hbase/trunk/src/main/java/org/apache/hadoop/hbase/client/Scan.java
* /hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java
* /hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java
* /hbase/trunk/src/test/java/org/apache/hadoop/hbase/client/TestOperation.java
> Slow Query Log
> --------------
>
> Key: HBASE-4117
> URL: https://issues.apache.org/jira/browse/HBASE-4117
> Project: HBase
> Issue Type: New Feature
> Components: ipc
> Reporter: Riley Patterson
> Assignee: Riley Patterson
> Priority: Minor
> Labels: client, ipc
> Fix For: 0.92.0
>
> Attachments: HBASE-4117-v2.patch, HBASE-4117-v3.patch, HBASE-4117.patch
>
>
> Produce log messages for slow queries. The RPC server will decide what is slow based on a configurable "warn response time" parameter. Queries designated as slow will then output a "response too slow" message followed by a fingerprint of the query, and a summary limited in size by another configurable parameter (to limit log spamming).
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira