[SERVER-36461] Add 'transaction' identifier to slow transaction log output Created: 06/Aug/18 Updated: 29/Oct/23 Resolved: 08/Aug/18 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Diagnostics, Replication |
| Affects Version/s: | None |
| Fix Version/s: | 4.0.2, 4.1.2 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | William Schultz (Inactive) | Assignee: | Nathan Louie |
| Resolution: | Fixed | Votes: | 0 |
| Labels: | per-txn-metrics | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||||||||||
| Backwards Compatibility: | Fully Compatible | ||||||||||||
| Operating System: | ALL | ||||||||||||
| Backport Requested: |
v4.0
|
||||||||||||
| Sprint: | Repl 2018-08-13 | ||||||||||||
| Participants: | |||||||||||||
| Description |
|
We should add an identifier to the log message for slow transactions so that we know the information logged corresponds to a transaction. This could be as simple as prefixing the log message with 'transaction'. Currently, slow transaction log messages look like the following:
We could change them to look to something like:
|
| Comments |
| Comment by Githook User [ 16/Aug/18 ] |
|
Author: {'username': 'nxlouie', 'email': 'nathan.louie@10gen.com', 'name': 'Nathan Louie'}Message: (cherry picked from commit 4b6a5591cf912f6cadaf2f1ede5d58ad2bb694c6) |
| Comment by Githook User [ 08/Aug/18 ] |
|
Author: {'name': 'Nathan Louie', 'email': 'nathan.louie@10gen.com', 'username': 'nxlouie'}Message: |
| Comment by William Schultz (Inactive) [ 07/Aug/18 ] |
|
Ok, we will go ahead and add a kTransaction logging component. |
| Comment by Esha Maharishi (Inactive) [ 07/Aug/18 ] |
|
I would just like to be careful not to log anything not related to transactions under kTransaction (e.g., we should not log anything for a retryable write under kTransaction). |
| Comment by Esha Maharishi (Inactive) [ 07/Aug/18 ] |
|
Yeah, sounds fine to me. I realize kSession is probably too general since sessions encompass so many different features (causal consistency, retryable writes, transactions). |
| Comment by Judah Schvimer [ 07/Aug/18 ] |
|
I think with renctan's refactor, the boundary between retryable writes and transactions will become a lot clearer as well which should reduce the chance that we introduce a new kTransaction log message that gets logged for retryable writes as well. |
| Comment by Tess Avitabile (Inactive) [ 07/Aug/18 ] |
|
I think it is fine to just create the kTransaction log component. I don't believe we have any logging at the moment about retryable writes, and that logging could go in the kWrite component anyway. And I don't believe we have any logging around session killing or expiration unrelated to transactions. I'm not aware of other transaction log messages, except for this one, which Randolph is removing because it is out of date. |
| Comment by Bruce Lucas (Inactive) [ 07/Aug/18 ] |
|
On the face of it I think it sounds like a good idea to log all transaction-related messages under a new TXN component. However I don't have a broad enough view of what those messages are to know whether that stands up to scrutiny. How much effort is it to identify all such messages to a) assess whether it makes sense and b) make the change if so? |
| Comment by William Schultz (Inactive) [ 07/Aug/18 ] |
|
Also, tess.avitabile judah.schvimer esha.maharishi are we OK with adding this as an isolated kTransaction log component to start, or do we think we should first add a kSession component and make this a child component of that? |
| Comment by William Schultz (Inactive) [ 07/Aug/18 ] |
|
spencer Are you implying we need to answer that question before we commit this change? |
| Comment by Spencer Brody (Inactive) [ 06/Aug/18 ] |
|
If we're adding a new TXN log component, do we need a separate ticket to switch existing txn-related log messages (if there are any) to use the new component? |
| Comment by William Schultz (Inactive) [ 06/Aug/18 ] |
|
Sounds good. We will add that. |
| Comment by Bruce Lucas (Inactive) [ 06/Aug/18 ] |
|
Yes I think both would be useful: TXN component to show that this relates to transactions generally, "transaction" to indicate this is reporting on a transaction per se (vs some other logging that might relate to transactions but not be reporting on the transaction as such, if that makes sense...) |
| Comment by William Schultz (Inactive) [ 06/Aug/18 ] |
|
For sake of time, we omitted adding the new logging component as part of the original ticket. If you think both would be useful, we can do both as part of this ticket. |
| Comment by Bruce Lucas (Inactive) [ 06/Aug/18 ] |
|
I think that's fine, but I think we also had decided to log them under a new component TXN since COMMAND isn't right as this is not a command as such. Can we make both changes as part of this ticket? |
| Comment by William Schultz (Inactive) [ 06/Aug/18 ] |
|
bruce.lucas Do you think this is a reasonable way to identify "slow" transactions in the log? My thought was that we should add something analogous to the "command: find" string that we would see in the logs for slow commands. If we don't add any identifier it is a bit difficult in my opinion to immediately identify that the log line actually represents information about a transaction. |