[SERVER-9438] Touch command not working on windows Created: 23/Apr/13  Updated: 10/Dec/14  Resolved: 09/Jan/14

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 2.4.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Gregor Macadam Assignee: Mark Benvenuto
Resolution: Done Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Windows 2008 R2


Issue Links:
Depends
Backwards Compatibility: Fully Compatible
Operating System: Windows
Participants:

 Description   

Restart mongodb, issue touch command for a collection's data and indexes.

Mongostat output taken while touch was running is shown below (shows data is page faulted into memory and resident goes up)

insert  query update delete getmore command flushes mapped  vsize    res faults              locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
    *0     *0     *0     *0       0     2|0       0    80m   308m    39m      2             local:0.0%          0       0|0     0|0   115b     5k     3   10:38:43
    *0     *0     *0     *0       0     2|0       0    80m   308m    39m      0             local:0.0%          0       0|0     0|0   115b     5k     3   10:38:44
    *0     *0     *0     *0       0     2|0       0    80m   308m    39m      0             local:0.0%          0       0|0     0|0   115b     5k     3   10:38:45
    *0     *0     *0     *0       0     2|0       0    80m   308m    39m      0             local:0.0%          0       0|0     0|0   115b     5k     3   10:38:46
    *0     *0     *0     *0       0     2|0       0    80m   308m    39m      0             local:0.0%          0       0|0     0|0   115b     5k     3   10:38:47
    *0     *0     *0     *0       0     2|0       0    80m   308m    39m      0             local:0.0%          0       0|0     0|0   115b     5k     3   10:38:48
    *0     *0     *0     *0       0     3|0       0    80m   309m    39m     15             local:0.0%          0       0|0     0|0   203b     5k     4   10:38:49
    *0     *0     *0     *0       0     2|0       0    80m   309m    39m      2             local:0.0%          0       0|0     0|0   115b     5k     4   10:38:50
    *0     *0     *0     *0       0     5|0       0    80m   309m    39m      0             local:0.0%          0       0|0     0|0   286b     6k     4   10:38:51
    *0     *0     *0     *0       0     2|0       0    80m   309m    39m      0             local:0.0%          0       0|0     0|0   115b     5k     4   10:38:52
insert  query update delete getmore command flushes mapped  vsize    res faults              locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
    *0     *0     *0     *0       0     2|0       0    80m   309m    39m      0             local:0.0%          0       0|0     0|0   115b     5k     4   10:38:53
    *0     *0     *0     *0       0     4|0       0   544m  1.21g    83m  11268                 .:0.2%          0       0|0     0|0   290b     5k     4   10:38:54
    *0     *0     *0     *0       0     2|0       0   544m  1.21g    83m      5             xxxx:0.0%          0       0|0     0|0   115b     7k     4   10:38:55
    *0     *0     *0     *0       0     2|0       0   544m  1.21g    83m     32             xxxx:0.0%          0       0|0     0|0   115b     7k     4   10:38:56
    *0     *0     *0     *0       0     2|0       0   544m  1.21g    83m      0             xxxx:0.0%          0       0|0     0|0   115b     7k     4   10:38:57
    *0     *0     *0     *0       0     2|0       0   544m  1.21g    83m      0             xxxx:0.0%          0       0|0     0|0   115b     7k     4   10:38:58
    *0     *0     *0     *0       0     2|0       0   544m  1.21g    83m      0             xxxx:0.0%          0       0|0     0|0   115b     7k     4   10:38:59
    *0     *0     *0     *0       0     2|0       0   544m  1.21g    83m      2             xxxx:0.0%          0       0|0     0|0   115b     7k     4   10:39:00

Run query db.collection.find() - this query runs slow and there is evidence from profiling of high timeAcquiringMicros , r and high numYield while this query takes place.

{
  "op" : "getmore",
  "ns" : "xxxx",
  "query" : { },
  "cursorid" : NumberLong("369564976120489"),
  "ntoreturn" : 0,
  "keyUpdates" : 0,
  "numYield" : 185,
  "lockStats" : {
    "timeLockedMicros" : {
      "r" : NumberLong(5482),
      "w" : NumberLong(0)
    },
    "timeAcquiringMicros" : {
      "r" : NumberLong(2970221),
      "w" : NumberLong(3)
    }
  },
  "nreturned" : 589,
  "responseLength" : 712048,
  "millis" : 2970,
  "ts" : ISODate("2013-04-23T09:18:57.007Z"),
  "client" : "10.194.144.71",
  "allUsers" : [],
  "user" : ""
}

Mongostat shows page faulting.

Run same query again - query runs fast. Mongostat shows page faulting.

RAM is 4GB, collection size is 13MB data, 2MB indexes.
Dedicated VM used for testing with no other queries running.



 Comments   
Comment by Mark Benvenuto [ 09/Jan/14 ]

It does work as expected in Windows.

There are things to be aware of
1. The Windows OS will cache the file in the file cache which means the only reliable way to repro issues is to reboot the box.
2. Page Faults in windows count both Soft and Hard. It will include memory allocation when you read the collection which is what he sees.

Generated at Thu Feb 08 03:20:25 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.