M312: Diagnostics and Debugging chapter 3 Slow Queries Learning Records

Keywords: Attribute MongoDB Python JSON

M312: Diagnostics and Debugging chapter 3 Slow Queries Learning Records

Running environment

Operating System: windows 10 Home Chinese Edition
Mongodb : Mongodb 3.4

Mongodb installation path: E:> MongoDB Server 3.4 bin\
Mongodb storage path: E:> MongoDB data

After-school questions

lab Building an Index in the Foreground in Production

Download Handouts:

m312/building_index_in_foreground.py
m312/set_up_building_index_in_foreground.sh

In this lab, you're going to simulate a foreground index build, in production.

Setup:

  • Download the handouts, and unpack. Place the following in your vagrant VM's shared directory:
    • set_up_building_index_in_foreground.sh
    • building_index_in_foreground.py
  • Download and unpack the employees.zip dataset and place it in your vagrant's /shared directory.
  • Run set_up_building_index_in_foreground.sh from the /shared directory within your VM, which will do each of the following:
    • Kill any mongod server processes running in the VM
    • Delete the ~/data directory
    • Start a replica set listening on ports 30000, 30001, and 30002.
    • Ensure that the server on port 30000 has the highest priority
    • Sleep for 20 seconds to ensure that a Primary has been elected
    • mongoimport the employees.json file into the m312.employees namespace.
  • Next, you'll want to simulate your application, and trigger your index build. If you've set everything up as described here, run building_index_in_foreground.py.

While this is going on, feel free to run mongostat against your server to get a feel for what's going on while your "application" is running.

The python script will do the following:

Your job is to go in and find the index build, plus any evidence of long-running read/update operations that occur as a result of the index build. Be careful not to mistake other operations (such as the mongoimport) for the index build.

Note:

You may find it helpful to rotate your log files , expecially if you run the python script more than once.

To demonstrate that you've identified both the index build, and the long-running operations, answer the following question:

When do the long-running operations begin to appear in the log files, based on their timestamps?

  • More than a minute before the index build began
  • Less than one second before the index build began
  • Less than one second after the index build began
  • More than one second after the index build began,and also more than one second before the index build ended
  • Less than one second before the index build ended
  • Less than one second after the index build ended
  • More than one second after the index build ended
  • More than a minute after the index build ended

Answer

Download the relevant files as required and extract them to path E: MongoDB m312 chapter_3_slow_queries m312

C:\Users\Shinelon>e:

E:\>cd MongoDB\m312\chapter_3_slow_queries\m312\m312-vagrant-env

E:\MongoDB\m312\chapter_3_slow_queries\m312\m312-vagrant-env>vagrant up

The installation package network is walled off. Change the network path in the provision-m312 file to one of the following connections (or manually download and rewrite the installation method in the provision-m312):

mongodb installation package

Enter relevant scripts into share folder:

E:\>copy MongoDB\m312\chapter_3_slow_queries\m312\building_index_in_foreground.py MongoDB\m312\chapter_3_slow_queries\m312\m312-vagrant-env\shared\
Already copied         One document.

E:\>copy MongoDB\m312\chapter_3_slow_queries\m312\set_up_building_index_in_foreground.sh MongoDB\m312\chapter_3_slow_queries\m312\m312-vagrant-env\shared\
Already copied         One document.

Manually download the employees.zip file and extract it to directory E: MongoDB m312 chapter_3_slow_queries m312 m312-vagrant-env shared

Execute the set_up_building_index_in_foreground.sh script as required by the title: ImportError: No module named psutil

root@m312:/home/vagrant# /shared/set_up_building_index_in_foreground.sh
mongod: no process found
rm: cannot remove Holmium?root/data Holmium? No such file or directoryry
Traceback (most recent call last):
  File "/usr/local/bin/mlaunch", line 7, in <module>
    from mtools.mlaunch.mlaunch import main
  File "/usr/local/lib/python2.7/dist-packages/mtools/mlaunch/mlaunch.py", line 6, in <module>
    import psutil
ImportError: No module named psutil
MongoDB shell version v3.4.2
connecting to: mongodb://127.0.0.1:30000/
2018-04-24T07:46:35.135+0000 W NETWORK  [thread1] Failed to connect to 127.0.0.1:30000, in(checking socket for error after poll), reason: Connection refused
2018-04-24T07:46:35.136+0000 E QUERY    [thread1] Error: couldn't connect to server 127.0.0.1:30000, connection attempt failed :
connect@src/mongo/shell/mongo.js:237:13
@(connect):1:6
exception: connect failed

This is due to the lack of psutil packages. Install psutil packages:

root@m312:/home/vagrant# sudo apt-get install python-psutil
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following NEW packages will be installed:
  python-psutil
0 upgraded, 1 newly installed, 0 to remove and 15 not upgraded.
Need to get 50.2 kB of archives.
After this operation, 299 kB of additional disk space will be used.
Get:1 http://archive.ubuntu.com/ubuntu/ trusty/main python-psutil amd64 1.2.1-1ubuntu2 [50.2 kB]
Fetched 50.2 kB in 7s (6,994 B/s)
Selecting previously unselected package python-psutil.
(Reading database ... 65034 files and directories currently installed.)
Preparing to unpack .../python-psutil_1.2.1-1ubuntu2_amd64.deb ...
Unpacking python-psutil (1.2.1-1ubuntu2) ...
Setting up python-psutil (1.2.1-1ubuntu2) ...

Execute the set_up_building_index_in_foreground.sh script again:

root@m312:/home/vagrant# /shared/set_up_building_index_in_foreground.sh
mongod: no process found
rm: cannot remove Holmium?root/data Holmium? No such file or directoryry
launching: mongod on port 30000
launching: mongod on port 30001
launching: mongod on port 30002
replica set 'm312RS' initialized.
MongoDB shell version v3.4.2
connecting to: mongodb://127.0.0.1:30000/
MongoDB server version: 3.4.2
{ "ok" : 1 }
bye
2018-04-24T07:48:23.243+0000    connected to: m312RS/m312:30000,m312:30001,m312:30002
2018-04-24T07:48:23.245+0000    dropping: m312.employees
2018-04-24T07:48:26.233+0000    [........................] m312.employees       13.5MB/395MB (3.4%)
2018-04-24T07:48:29.233+0000    [#.......................] m312.employees       29.0MB/395MB (7.3%)
2018-04-24T07:48:32.233+0000    [##......................] m312.employees       43.3MB/395MB (11.0%)
2018-04-24T07:48:35.232+0000    [###.....................] m312.employees       58.4MB/395MB (14.8%)
2018-04-24T07:48:38.233+0000    [####....................] m312.employees       72.8MB/395MB (18.4%)
2018-04-24T07:48:41.233+0000    [#####...................] m312.employees       86.2MB/395MB (21.8%)
2018-04-24T07:48:44.233+0000    [######..................] m312.employees       101MB/395MB (25.5%)
2018-04-24T07:48:47.232+0000    [#######.................] m312.employees       115MB/395MB (29.2%)
2018-04-24T07:48:50.233+0000    [#######.................] m312.employees       117MB/395MB (29.7%)
2018-04-24T07:48:53.233+0000    [#######.................] m312.employees       118MB/395MB (29.8%)
2018-04-24T07:48:56.234+0000    [#######.................] m312.employees       122MB/395MB (30.8%)
2018-04-24T07:48:59.237+0000    [#######.................] m312.employees       128MB/395MB (32.4%)
2018-04-24T07:49:02.232+0000    [########................] m312.employees       134MB/395MB (34.0%)
2018-04-24T07:49:05.233+0000    [########................] m312.employees       139MB/395MB (35.2%)
2018-04-24T07:49:08.234+0000    [########................] m312.employees       145MB/395MB (36.8%)
2018-04-24T07:49:11.233+0000    [#########...............] m312.employees       152MB/395MB (38.5%)
2018-04-24T07:49:14.234+0000    [#########...............] m312.employees       158MB/395MB (40.0%)
2018-04-24T07:49:17.233+0000    [#########...............] m312.employees       164MB/395MB (41.6%)
2018-04-24T07:49:20.233+0000    [##########..............] m312.employees       171MB/395MB (43.2%)
2018-04-24T07:49:23.233+0000    [##########..............] m312.employees       177MB/395MB (44.9%)
2018-04-24T07:49:26.233+0000    [###########.............] m312.employees       183MB/395MB (46.4%)
2018-04-24T07:49:29.232+0000    [###########.............] m312.employees       188MB/395MB (47.6%)
2018-04-24T07:49:32.234+0000    [###########.............] m312.employees       189MB/395MB (48.0%)
2018-04-24T07:49:35.233+0000    [###########.............] m312.employees       196MB/395MB (49.5%)
2018-04-24T07:49:38.235+0000    [############............] m312.employees       201MB/395MB (51.0%)
2018-04-24T07:49:41.233+0000    [############............] m312.employees       207MB/395MB (52.5%)
2018-04-24T07:49:44.232+0000    [############............] m312.employees       213MB/395MB (54.0%)
2018-04-24T07:49:47.235+0000    [#############...........] m312.employees       219MB/395MB (55.5%)
2018-04-24T07:49:50.233+0000    [#############...........] m312.employees       226MB/395MB (57.1%)
2018-04-24T07:49:53.233+0000    [##############..........] m312.employees       232MB/395MB (58.7%)
2018-04-24T07:49:56.233+0000    [##############..........] m312.employees       238MB/395MB (60.2%)
2018-04-24T07:49:59.233+0000    [##############..........] m312.employees       244MB/395MB (61.9%)
2018-04-24T07:50:02.234+0000    [###############.........] m312.employees       251MB/395MB (63.5%)
2018-04-24T07:50:05.233+0000    [###############.........] m312.employees       254MB/395MB (64.3%)
2018-04-24T07:50:08.234+0000    [###############.........] m312.employees       254MB/395MB (64.4%)
2018-04-24T07:50:11.233+0000    [###############.........] m312.employees       260MB/395MB (65.9%)
2018-04-24T07:50:14.233+0000    [################........] m312.employees       266MB/395MB (67.4%)
2018-04-24T07:50:17.232+0000    [################........] m312.employees       272MB/395MB (69.0%)
2018-04-24T07:50:20.233+0000    [################........] m312.employees       278MB/395MB (70.5%)
2018-04-24T07:50:23.234+0000    [#################.......] m312.employees       284MB/395MB (72.1%)
2018-04-24T07:50:26.232+0000    [#################.......] m312.employees       290MB/395MB (73.5%)
2018-04-24T07:50:29.235+0000    [##################......] m312.employees       297MB/395MB (75.1%)
2018-04-24T07:50:32.235+0000    [##################......] m312.employees       303MB/395MB (76.8%)
2018-04-24T07:50:35.240+0000    [##################......] m312.employees       309MB/395MB (78.3%)
2018-04-24T07:50:38.233+0000    [###################.....] m312.employees       316MB/395MB (80.0%)
2018-04-24T07:50:41.233+0000    [###################.....] m312.employees       317MB/395MB (80.4%)
2018-04-24T07:50:44.233+0000    [###################.....] m312.employees       323MB/395MB (81.8%)
2018-04-24T07:50:47.233+0000    [###################.....] m312.employees       326MB/395MB (82.7%)
2018-04-24T07:50:50.233+0000    [####################....] m312.employees       332MB/395MB (84.1%)
2018-04-24T07:50:53.233+0000    [####################....] m312.employees       338MB/395MB (85.7%)
2018-04-24T07:50:56.233+0000    [####################....] m312.employees       344MB/395MB (87.2%)
2018-04-24T07:50:59.234+0000    [#####################...] m312.employees       351MB/395MB (88.8%)
2018-04-24T07:51:02.233+0000    [#####################...] m312.employees       357MB/395MB (90.4%)
2018-04-24T07:51:05.234+0000    [######################..] m312.employees       363MB/395MB (92.0%)
2018-04-24T07:51:08.232+0000    [######################..] m312.employees       369MB/395MB (93.6%)
2018-04-24T07:51:11.233+0000    [######################..] m312.employees       371MB/395MB (94.0%)
2018-04-24T07:51:14.233+0000    [######################..] m312.employees       375MB/395MB (94.9%)
2018-04-24T07:51:17.233+0000    [#######################.] m312.employees       380MB/395MB (96.3%)
2018-04-24T07:51:20.236+0000    [#######################.] m312.employees       386MB/395MB (97.8%)
2018-04-24T07:51:23.233+0000    [#######################.] m312.employees       391MB/395MB (99.1%)
2018-04-24T07:51:25.282+0000    [########################] m312.employees       395MB/395MB (100.0%)
2018-04-24T07:51:25.282+0000    imported 1010893 documents

Run the script build_index_in_foreground.py:

root@m312:/home/vagrant# /shared/building_index_in_foreground.py
Looks like the employees collection is already present.
  Not going to re-import it. Dropping indexes...  done.
Spawning a set of processes to do lots of reads and writes while I create an index. The processes will simulate your many application clients.
  ... ok. While your 'application' clients are running, I'm going to create an index on {last_name: 1, first_name: 1}.
  ... ok, done.
Your log files should be ready for you to look at!

Enter the replica set environment:

vagrant@m312:~$ mongo --port 30000
MongoDB shell version v3.4.2
connecting to: mongodb://127.0.0.1:30000/
MongoDB server version: 3.4.2
Welcome to the MongoDB shell.
For interactive help, type "help".
For more comprehensive documentation, see
        http://docs.mongodb.org/
Questions? Try the support group
        http://groups.google.com/group/mongodb-user
Server has startup warnings:
2018-04-24T07:48:01.748+0000 I STORAGE  [initandlisten]
2018-04-24T07:48:01.748+0000 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2018-04-24T07:48:01.748+0000 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
2018-04-24T07:48:01.884+0000 I CONTROL  [initandlisten]
2018-04-24T07:48:01.884+0000 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2018-04-24T07:48:01.884+0000 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2018-04-24T07:48:01.884+0000 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
2018-04-24T07:48:01.884+0000 I CONTROL  [initandlisten]

View logs:

MongoDB Enterprise m312RS:PRIMARY> use local
switched to db local
MongoDB Enterprise m312RS:PRIMARY> db.oplog.rs.find()
{ "ts" : Timestamp(1524556082, 1), "h" : NumberLong("4463326453374821604"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "initiating set" } }
{ "ts" : Timestamp(1524556094, 2), "t" : NumberLong(1), "h" : NumberLong("8377794278341915314"), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "new primary" } }
{ "ts" : Timestamp(1524556103, 1), "t" : NumberLong(1), "h" : NumberLong("-8950094261114613335"), "v" : 2, "op" : "c", "ns" : "m312.$cmd", "o" : { "create" : "employees", "idIndex" : { "v" : 2, "key" : { "_id" : 1 }, "name" : "_id_", "ns" : "m312.employees" } } }
{ "ts" : Timestamp(1524556103, 2), "t" : NumberLong(1), "h" : NumberLong("510266152817245486"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857c5"), "last_name" : "Pham", "quote" : "Aliquam est reiciendis alias neque ad.", "job" : "Counselling psychologist", "ssn" : "401-31-6615", "address" : { "city" : "Lake Meaganton", "state" : "Idaho", "street" : "83248 Woods Extension", "zip" : "10914-3394" }, "first_name" : "Yvonne", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2011-04-17T21:19:28Z"), "email" : "murillobrian@cox.net" } }
{ "ts" : Timestamp(1524556103, 3), "t" : NumberLong(1), "h" : NumberLong("2272078709834620109"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857c6"), "last_name" : "Nelson", "quote" : "A eveniet iusto dicta quis sed tenetur eius illo.", "job" : "Conservator, furniture", "ssn" : "671-16-1433", "address" : { "city" : "Lake Meaganton", "state" : "Idaho", "street" : "699 Ryan Branch Apt. 371", "zip" : "10914-3394" }, "first_name" : "Mary", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2016-04-27T11:04:11Z"), "email" : "cindy93@gmail.com" } }
{ "ts" : Timestamp(1524556103, 4), "t" : NumberLong(1), "h" : NumberLong("-3423843438153384604"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857c7"), "last_name" : "Hull", "quote" : "Sunt consectetur harum maxime qui.", "job" : "Private music teacher", "ssn" : "042-41-2995", "address" : { "city" : "Phelpston", "street" : "11869 Stewart Ports Apt. 924", "zip" : "89388" }, "first_name" : "Carrie", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2017-03-06T08:40:34Z"), "email" : "csmith@hall.biz" } }
{ "ts" : Timestamp(1524556103, 5), "t" : NumberLong(1), "h" : NumberLong("-2748583038735912885"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857c8"), "last_name" : "Frazier", "quote" : "Minus quo corporis nemo id provident eius.", "job" : "Investment banker, corporate", "ssn" : "683-46-9400", "address" : { "city" : "Lake Meaganton", "state" : "Idaho", "street" : "7526 David Island Apt. 404", "zip" : "10914-3394" }, "first_name" : "John", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2014-05-26T00:14:02Z"), "email" : "ythompson@hotmail.com" } }
{ "ts" : Timestamp(1524556103, 6), "t" : NumberLong(1), "h" : NumberLong("-4272853794543634317"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857c9"), "last_name" : "Herrera", "quote" : "Sit perferendis nostrum suscipit cumque mollitia.", "job" : "Theatre stage manager", "ssn" : "261-99-7098", "address" : { "city" : "Brewershire", "street" : "9069 Bailey Ferry Suite 423", "zip" : "51376" }, "first_name" : "Elizabeth", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2016-05-23T05:14:41Z"), "email" : "elizabeth35@mccarty.com" } }
{ "ts" : Timestamp(1524556103, 7), "t" : NumberLong(1), "h" : NumberLong("-4160213891465004502"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857ca"), "last_name" : "Liu", "quote" : "Voluptatum aspernatur illo inventore fuga eius fugiat similique corrupti.", "job" : "Physiotherapist", "ssn" : "273-71-8889", "address" : { "city" : "Leeport", "street" : "59105 Adkins Ramp Apt. 451", "zip" : "89662" }, "first_name" : "Anthony", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2015-05-23T02:21:50Z"), "email" : "asimmons@hotmail.com" } }
{ "ts" : Timestamp(1524556103, 8), "t" : NumberLong(1), "h" : NumberLong("-5526899559426671528"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857cb"), "last_name" : "Stevens", "quote" : "Doloribus sequi temporibus eveniet.", "job" : "Engineer, civil (contracting)", "ssn" : "081-78-3110", "address" : { "city" : "Anthonyhaven", "street" : "1914 Madison Fords", "zip" : "53666" }, "first_name" : "Richard", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2010-03-28T14:20:13Z"), "email" : "david58@yahoo.com" } }
{ "ts" : Timestamp(1524556103, 9), "t" : NumberLong(1), "h" : NumberLong("-1001455799138112190"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857cc"), "last_name" : "Perry", "quote" : "Tempore sunt quae temporibus in nostrum.", "job" : "Environmental consultant", "ssn" : "248-70-8696", "address" : { "city" : "Jamesfurt", "street" : "4961 Obrien Keys", "zip" : "19133" }, "first_name" : "Trevor", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2013-05-27T13:24:31Z"), "email" : "teresabrown@yahoo.com" } }
{ "ts" : Timestamp(1524556103, 10), "t" : NumberLong(1), "h" : NumberLong("7319744338376850087"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857cd"), "last_name" : "Gibson", "quote" : "Temporibus accusamus cupiditate tempore atque.", "job" : "Artist", "ssn" : "572-94-3935", "address" : { "city" : "Debrafurt", "street" : "06878 Chapman Pine", "zip" : "32933" }, "first_name" : "Sara", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2016-12-17T19:09:18Z"), "email" : "mhall@sims-moss.info" } }
{ "ts" : Timestamp(1524556103, 11), "t" : NumberLong(1), "h" : NumberLong("-8254524138374999338"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857ce"), "last_name" : "Turner", "quote" : "Vero iste odit voluptas sunt harum totam.", "job" : "Purchasing manager", "ssn" : "579-34-3243", "address" : { "city" : "Kellyhaven", "street" : "3096 Jones Parkway Suite 928", "zip" : "09697" }, "first_name" : "Nicholas", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2013-09-25T07:20:41Z"), "email" : "steven03@hancock.info" } }
{ "ts" : Timestamp(1524556103, 12), "t" : NumberLong(1), "h" : NumberLong("915927080282861600"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857cf"), "last_name" : "Johnson", "quote" : "Dolorum odio molestias harum sunt sint.", "job" : "Special effects artist", "ssn" : "067-63-2867", "address" : { "city" : "Lake Meaganton", "state" : "Idaho", "street" : "55634 Scott Springs", "zip" : "10914-3394" }, "first_name" : "Keith", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2012-08-30T05:41:55Z"), "email" : "mjones@walker.com" } }
{ "ts" : Timestamp(1524556103, 13), "t" : NumberLong(1), "h" : NumberLong("-5092246712154353018"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857d0"), "last_name" : "Tucker", "quote" : "Enim rerum perspiciatis pariatur ipsam sed.", "job" : "Scientist, forensic", "ssn" : "333-53-2162", "address" : { "city" : "Lake Meaganton", "state" : "Idaho", "street" : "9307 Christopher Street Suite 319", "zip" : "10914-3394" }, "first_name" : "Kristine", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2011-06-20T12:02:25Z"), "email" : "usalazar@yahoo.com" } }
{ "ts" : Timestamp(1524556103, 14), "t" : NumberLong(1), "h" : NumberLong("-2206896415529188900"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857d1"), "last_name" : "Combs", "quote" : "Laborum perferendis dolorum rerum eius ipsa odit.", "job" : "Accountant, chartered certified", "ssn" : "136-13-3672", "address" : { "city" : "Lake Meaganton", "state" : "Idaho", "street" : "262 Donna Ports", "zip" : "10914-3394" }, "first_name" : "Jacqueline", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2016-01-06T01:47:09Z"), "email" : "kathleen81@gmail.com" } }
{ "ts" : Timestamp(1524556103, 15), "t" : NumberLong(1), "h" : NumberLong("333343584211571593"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857d2"), "last_name" : "Owens", "quote" : "Sit quisquam id quidem voluptate consequuntur totam totam.", "job" : "Fisheries officer", "ssn" : "875-23-9138", "address" : { "city" : "Lake Meaganton", "state" : "Idaho", "street" : "81799 Nelson Forks Suite 297", "zip" : "10914-3394" }, "first_name" : "Robert", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2015-12-17T18:51:12Z"), "email" : "joshua24@harding-miller.biz" } }
{ "ts" : Timestamp(1524556103, 16), "t" : NumberLong(1), "h" : NumberLong("6372524148305143811"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857d3"), "last_name" : "Simon", "quote" : "Laboriosam incidunt minus vero voluptates officiis.", "job" : "Operational investment banker", "ssn" : "740-65-7137", "address" : { "city" : "Rogershire", "street" : "8041 Smith Gardens", "zip" : "60705" }, "first_name" : "Tanner", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2011-07-21T04:06:14Z"), "email" : "julie90@gmail.com" } }
{ "ts" : Timestamp(1524556103, 17), "t" : NumberLong(1), "h" : NumberLong("2361209461982062260"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857d4"), "last_name" : "Cole", "quote" : "At aut debitis alias itaque modi autem.", "job" : "Insurance broker", "ssn" : "821-30-8939", "address" : { "city" : "Lake Meaganton", "state" : "Idaho", "street" : "955 Kayla Manor", "zip" : "10914-3394" }, "first_name" : "Julia", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2015-12-30T09:26:58Z"), "email" : "owallace@yahoo.com" } }
{ "ts" : Timestamp(1524556103, 18), "t" : NumberLong(1), "h" : NumberLong("-867703067546619547"), "v" : 2, "op" : "i", "ns" : "m312.employees", "o" : { "_id" : ObjectId("5adee147db67512a034857d5"), "last_name" : "Fitzpatrick", "quote" : "Id amet id itaque.", "job" : "General practice doctor", "ssn" : "028-40-3851", "address" : { "city" : "Lake Meaganton", "state" : "Idaho", "street" : "69994 Booker Estate Apt. 230", "zip" : "10914-3394" }, "first_name" : "Lisa", "company_id" : ObjectId("58bdbe32500b1d42c7e10be7"), "employer" : "Terry and Sons", "birthday" : ISODate("2013-12-03T09:21:26Z"), "email" : "cynthia99@dalton.info" } }
Type "it" for more

It was observed that the time stamp for index creation was Timestamp(1524556103, 1)

The time stamps before and after it are: (1524556094, 2), (1524556103, 2)

It can be understood as:
more than 1 second before index build began
less than 1 second after index build ended

So the correct answer is:

  • Less than one second after the index build ended

lab: Analyse Profiler Data

Download Handouts:

m312/lab_analyse_profiler/profile.json

In this lab, you are tasked to determine when a given event happened by analysing the system.profiler data.

This profiler information was captured during the execution of test script performing read operations. These read operations, consisted on 3 types of queries:

  • query on _id field -> db.employees.find({_id: XXXX})
  • query on address.zip field -> db.employees.find({"address.zip": XXX })
  • range query on birthday field -> db.employees.find({"birthday": {"gt":X,"gt":X,"lt": X }})

To analyse the profiler data, we are going to use the best database in the world that, as you all know, is MongoDB.

Let's go ahead and setup the environment.

  • First step, launch a single node mongod instance:
cd m312-vagrant-env
vagrant up
vagrant ssh
mlaunch --single
  • The following step is to download the attached profile.json data and make it available in your m312 virtual machine:
cp Downloads/profiler*.json m312-vagrant-env/dataset

The command line example is set for Unix but a simple copy of this file will suffice

  • Next, we will load the dataset into our single node mongod instance. Let's load the data into a collection named profiler_data
vagrant ssh
mongoimport -d m312 -c profiler_data /dataset/profile.json

The profiler data contains all read operations that surpassed the threshold of 40ms, the set slowms value:

db.setProfilingLevel(1, 40)

During the execution of our script, our DBAs decided to create an index that affected the behavior of one of the offending queries.

From the profiler data, we are asked to determined which index was created and when was this change reflected on the behavior of our query.

So in this lab we want to know:

When and which index was created ?

Choose the best answer:

db.companies.createIndex({'address.zip': 1}) 
After 2017-03-06T22:57:00.039Z
db.employees.createIndex({'address.zip': 1}) 
After 2017-03-06T22:55:55.065Z
db.employees.createIndex({'birthdate': 1}) 
After 2017-03-06T22:57:00.039Z
db.employees.createIndex({'birthdate': 1}) 
Before 2017-03-06T22:57:57.332Z
db.employees.createIndex({'address.zip': 1}) 
After 2017-03-06T22:56:30.407Z

Answer

Exit and re-enter the container:

E:\MongoDB\m312\chapter_3_slow_queries\m312\m312-vagrant-env>vagrant ssh
Welcome to Ubuntu 14.04.5 LTS (GNU/Linux 3.13.0-144-generic x86_64)

 * Documentation:  https://help.ubuntu.com/

  System information as of Tue Apr 24 07:29:48 UTC 2018

  System load:  0.0               Processes:           85
  Usage of /:   3.7% of 39.34GB   Users logged in:     0
  Memory usage: 4%                IP address for eth0: 10.0.2.15
  Swap usage:   0%                IP address for eth1: 192.168.14.100

  Graph this data and manage this system at:
    https://landscape.canonical.com/

  Get cloud support with Ubuntu Advantage Cloud Guest:
    http://www.ubuntu.com/business/services/cloud

New release '16.04.4 LTS' available.
Run 'do-release-upgrade' to upgrade to it.


*** System restart required ***
Last login: Tue Apr 24 07:29:49 2018 from 10.0.2.2

Start a single node instance:

vagrant@m312:~$ mlaunch --single
launching: mongod on port 27017

Download profile.json file and put it in path E: MongoDB m312 chapter_3_slow_queries m312 m312-vagrant-env dataset

Import scripts:

vagrant@m312:~$ mongoimport -d m312 -c profiler_data /dataset/profile.json
2018-04-24T08:51:19.449+0000    connected to: localhost
2018-04-24T08:51:19.501+0000    imported 195 documents

Enter the mongo shell and configure the analysis level:

vagrant@m312:~$ mongo
MongoDB shell version v3.4.2
connecting to: mongodb://127.0.0.1:27017
MongoDB server version: 3.4.2
Server has startup warnings:
2018-04-24T08:48:11.592+0000 I STORAGE  [initandlisten]
2018-04-24T08:48:11.592+0000 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2018-04-24T08:48:11.592+0000 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
2018-04-24T08:48:11.693+0000 I CONTROL  [initandlisten]
2018-04-24T08:48:11.693+0000 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2018-04-24T08:48:11.693+0000 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2018-04-24T08:48:11.693+0000 I CONTROL  [initandlisten]
MongoDB Enterprise > db.setProfilingLevel(1, 40)
{ "was" : 0, "slowms" : 100, "ok" : 1 }

View the profiler_data collection:

MongoDB Enterprise > use m312
switched to db m312
MongoDB Enterprise > show collections
profiler_data
MongoDB Enterprise > db.profiler_data.find().count
function (applySkipLimit) {
    var cmd = this._convertToCountCmd(applySkipLimit);

    var res = this._db.runReadCommand(cmd);
    if (res && res.n != null)
        return res.n;
    throw _getErrorWithCode(res, "count failed: " + tojson(res));
}
MongoDB Enterprise > db.profiler_data.find().count()
195

To analyze the topic, you should look for records that use an index (not a full table scan):

MongoDB Enterprise > db.profiler_data.find({"$nor":[{"planSummary" : "COLLSCAN"}]},{"_id":0,"planSummary":1,"ts":1})
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:56:30.407Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:56:31.579Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:57:00.039Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:57:42.188Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:57:57.332Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:58:06.581Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:58:10.604Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:58:12.412Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:58:47.868Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:58:49.977Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:58:52.015Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:58:55.367Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:58:56.807Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:59:08.078Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:59:10.228Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:59:23.411Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:59:26.937Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:59:41.204Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:59:43.138Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:59:48.636Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:59:54.835Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T22:59:57.930Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T23:00:17.057Z") }
{ "planSummary" : "IXSCAN { address.zip: 1 }", "ts" : ISODate("2017-03-06T23:00:21.825Z") }

The results show that the answer is

db.employees.createIndex({'address.zip': 1}) 
After 2017-03-06T22:55:55.065Z

Posted by Vex on Tue, 05 Feb 2019 18:30:18 -0800