[SERVER-7107] Queries/getmores generate write lock stats in system.profile Created: 21/Sep/12 Updated: 06/Dec/22 Resolved: 22/Aug/19 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Concurrency, Internal Code |
| Affects Version/s: | 2.2.0 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Scott Hernandez (Inactive) | Assignee: | Backlog - Query Team (Inactive) |
| Resolution: | Done | Votes: | 3 |
| Labels: | query-44-grooming | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||||||
| Assigned Teams: |
Query
|
||||||||
| Operating System: | ALL | ||||||||
| Participants: | |||||||||
| Description |
|
After investigating this more, and discussing this with others, here is what I've found:
Originally I had expected, as did the users who noticed this, that "lockStats.timeAcquiringMicros.w" should be zero since it was a read-only operation.
|
| Comments |
| Comment by David Storch [ 16/Aug/19 ] | ||||||||||||||||||||||||||||||||||||||||||||||
|
I cannot reproduce this trivially by running a query with profiling level 2 enabled on the master branch. Looking at the code, it appears that we might be gathering and serializing the lock stats before we ever acquire the locks needed to write to the profile collection. I'm flagging for re-triage. We may want to spend some time investigating to confirm whether this issue has been fixed. | ||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Asya Kamsky [ 18/Jul/16 ] | ||||||||||||||||||||||||||||||||||||||||||||||
|
Still happening in 3.3.9
More details for a single one:
| ||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Andy Schwerin [ 08/Mar/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||
|
scotthernandez, please refine the description, then unassign and move to fixVersion = Needs Triage. | ||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Scott Hernandez (Inactive) [ 16/Nov/12 ] | ||||||||||||||||||||||||||||||||||||||||||||||
|
I turned on profiling at level 2 for all these tests, and the ones above. I did a little more testing and found that in consecutive runs that the lock time is 0, but the acquire time is somewhere between 3-6micros. To further testing I times a few inserts (after priming the extent with a write or two) and the lock time is much greater than the lock acquire time by many times. I also tested on a capped collection and it resulted in the same behavior of the lock acquisition being much much lower than the write lock time. I haven't looked at the code but if the lock times include the global lock that may be a possible explanation. | ||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Scott Hernandez (Inactive) [ 21/Sep/12 ] | ||||||||||||||||||||||||||||||||||||||||||||||
|
No journaling on osx.
|