[Performance]: Taking 20 seconds to do a single query

[samebchase]

Hey, I was glad to find this Raku Mongo library.

I tried following the docs, and did a simple query on a field that is indexed. It took 22 seconds to print the result.

Am I doing something wrong?

#!/usr/bin/env raku

use v6;

use BSON::Document;
use MongoDB::Client;
use MongoDB::Database;
use MongoDB::Collection;

sub MAIN($db, $collection, $id) {

    my MongoDB::Client $client .= new(:uri('mongodb://127.0.0.1:27017'));
    my MongoDB::Database $database = $client.database($db);
    my MongoDB::Collection $coll = $database.collection($collection);

    my MongoDB::Cursor $cursor = $coll.find(:number-to-return(1));
    $cursor.fetch.perl.say;
}

This is on Mongo version 3.0.15, with the latest library version installed from zef.

[MARTIMM]

I've tested this too to be sure. Indeed it takes time. There are several places in the code where time is lost;

• building up a connection
• checking the server type you're talking to (standalone, replica, etc) After that, when more data is asked in the same run, the data comes more quickly.

I have to say that it is a long time ago that I have looked at this project and must review the code to see if anything can be improved.

So in short, there is not much I can do to improve the code immediately.

[samebchase]

@MARTIMM: Please give me some pointers based on what hunches you have, I can also take a look at the code and try and profile it however best I can. It will be a good learning experience for me.

When I used time on the script, this is what I got, and based on IRC discussions in #raku, they suggested that somewhere a lot of waiting is happening. Could there be some misconfiguration on my end, how I set up the client, connection or database object. They said something like "user-time is how fast the program could potentially run, if it doesn't do all that waiting".

real    0m22.649s
user    0m2.960s
sys     0m0.096s

If you are indeed able to isolate the cause for the long running time, you can file it as a task. Perhaps if I get some free time I may be able to pick it up.

[xdg]

Instead of find, I suggesting using run-command (Database method) and sending [ping => 1] (in Perl 5 terms, not sure what the Raku equivalent is). That will help isolate whether the problems are with making the initial connection or with executing the query and iterating the cursor.

[xdg]

You could also look at your database logs to see when different commands are arriving at the server to get a sense of where things are slow in the client.

[MARTIMM]

Hi @xdg, thanks for stepping in. I've done a ping that returns in about 10 sec with the code below. However, when the command is run twice, the second is finished in about 0.02 sec.

use v6;

use BSON::Document;
use MongoDB::Client;
use MongoDB::Database;

sub MAIN( ) {

  my MongoDB::Client $client .= new(
    :uri('mongodb://192.168.0.253:65140/?replicaSet=MetaLibrary')
  );

  my MongoDB::Database $database = $client.database('Library');

  my $t0 = now;

  my $doc = $database.run-command(BSON::Document.new: (ping => 1));
  say now - $t0;

  $doc = $database.run-command(BSON::Document.new: (ping => 1));
  say now - $t0;
}

P.s. Here I am using my own server which is a replica server set of two servers on another system.

When I do this with the original question, i.e. getting data using find, I see about the same time spent for the first call (10.1 sec) and the second call needs only 0.1 sec.

The system needs about 10 sec to get ready and to get its administration done. this is proved by adding a sleep of 10 sec just before the first call. Now the find call needs 0.1 sec just like the second.

This gives me also an idea of where to look at in the code. I remember that there are several periods of sleep build in just to be sure that I get the info from the server before continuing. B.t.w. this time is spent every time that a client is initialized.

[MARTIMM]

Running the program with logging on, I see that testing, which happens in a loop, comes up with a server quite quickly but stays testing just to be sure every bit of info is found. I could perhaps insert a boolean which flips when a workable situation is found. E.g. seeing a master or primary server.

[xdg]

Ideally, the Raku driver should follow these two specifications:

• Server Discovery and Monitoring (SDAM)
• Server Selection

The SDAM spec defines a state machine for processing ismaster responses that switches into a 'ready for work' state ASAP. The Server Selection spec uses state from SDAM to decide when to send a command/query versus when/how to loop waiting for an SDAM update.

The Perl 5 code for this is mostly here: https://github.com/mongodb/mongo-perl-driver/blob/master/lib/MongoDB/_Topology.pm

Unfortunately, it's single threaded, which, IIUC, Raku shouldn't need to do. The Python driver might be a better model -- much of its related code is here: https://github.com/mongodb/mongo-python-driver/blob/master/pymongo/topology.py

[MARTIMM]

Thanks, @xdg, I've read those docs and most of it is implemented using several threads (which doesn't say that my code cannot be improved :-). I test this ismaster response and build up the topology status, but it isn't ASAP what I tried to say above. I need to insert some sort of test on a 'workable situation'. This can happen before every server test is completed.

[MARTIMM]

Reading the documents again, I see that it is much improved and more clear what every step does in the process, so I need a good reread and a rewrite of the server discovery process. In the meantime, my Raku knowledge is also improved so I can perhaps create a better solution. So;

• First a quick solution with a boolean
• Then maybe a rewrite to get everything implemented, which wasn't completely the case.

[samebchase]

@MARTIMM: Available for any assistance you need. 👍

[MARTIMM]

Thanks very much, Samuel. I think the first thing would be quickly solved. I find it hard to divide the tasks in such a way that you can do something in the code. It will be a steep hill to climb too. Also, I have to rewrite the discovery part too following the documents mentioned by David Golden. This will then destroy your work too.

The trouble at hand is something completely different though. My laptop screen broke down so I have to rebuild my development environment on another computer. Almost done though...

[samebchase]

@MARTIMM: Sure thing! Thanks for taking the time to look into this.

[MARTIMM]

Strange as it is... I am now settled on a new development environment and tried to test with the same programs as before using the ping run command. It now repeatedly shows better results as before without changing a bit of the code. What can be different though is the following;

• Raku version used: This is Rakudo version 2020.05.1-56-g25f8395cf built on MoarVM version 2020.05 implementing Raku 6.d. It might be that threads are handled a bit differently. I repeatedly see that as soon a topology is set, that the command continues which I have seen in my code it should.
• Tests now done on a slightly faster system but still Intel i7 (later version) and more memory.

On some occasions, I see that it is slow like before but after that, I get responses of 0.5 sec.

So the suggestion is that you try it too on the latest Raku version. I assume you already have the latest Mongo driver code (version 0.43.2).

For the moment I leave it by this and start working on improving the discovery mechanism suggested by David above.

[samebchase]

Tried this out multiple times with a freshly built Rakudo version 2020.05.1 and it is consistently taking 23 seconds. I am also going to try it on the bleeding edge version in some time.

Do you expect that with the new server discovery mechanism, it will be much faster?

Available for help with testing, code-review etc, so let me know. I am planning to read those Mongo specification documents.

[samebchase]

Also, tried with Rakudo version 2020.05.1-121-gadfa192 built on MoarVM version 2020.05-12-g3605efd and still got the same result.

[MARTIMM]

Sorry to hear that. So it isn't a new Raku compiler in my case that made the difference. But somehow I get the feeling that there is something with threads behaving differently. For instance, a sleep in a thread does not switch a thread in your case. So the other thread, which waits on the result doesn't do much to start the I/O. I'll look into it and may have to rewrite that part.

[samebchase]

It's a Ubuntu Linux VM with a single core. My Mongo instance is running inside the VM. Could that have anything do with it? The library did not install on Mac after multiple attempts, so I decided to run it directly inside the VM.

You mentioned that the delay happens occasionally for you. Do you have any hunch why that is happening?

I will try on my main Linux machine and report back.

[MARTIMM]

Yes, I can imagine that that is a problem. Your system manages to switch between those 'threads' but might stay longer in a 'thread' than a real multi-core system. sleeping in a thread is perhaps not the proper way to let the system choose another thread available to run. It supports the idea of mine to rewrite parts of the mechanism to make shorter-lived threads to be able to switch quickly. However, there is one thread in the background, monitoring the behavior of all servers when everything is stable and running. I don't see this quickly changed.

I don't have any idea why the test sometimes takes more time, it is rare that I see it.

[samebchase]

Ah, so that explains it. Thanks so much for getting to the bottom of this. Have a wonderful day! :-D

[MARTIMM]

I have made some changes in Client, Server, and Monitor. It now shows times of about 0.37 sec on my machine. To test it you can do the following;

git clone --branch discovery-rewrite https://github.com/MARTIMM/mongo-perl6-driver
cd mongo-perl6-driver
zef install .

later to revert back to your original version

zef uninstall 'MongoDB:ver<0.43.9>'

The test you can run after installation is stored in Tests/issue31b.pl6 You'll have to change the port number perhaps. The test prepares a client, then issues a ping using run-command(). It repeats the ping command, then clears the client by initializing it again and another ping. To test the issue after installing (first prove6 is for creating sandbox and start servers and second prove6 is to stop servers and remove sandbox);

> prove6 t/0*
> raku Test/issue31b.pl6
> prove t/9*

The log output

--------------------------------------------------------------------------------
2020-05-18 10:17

34.863121 [D][1][Uri][112]: parse mongodb://localhost:65013/
34.866588 [D][1][Client][105]: Found 1 servers in uri
34.867060 [D][1][Client][109]: todo: localhost:65013
34.877810 [D][1][Monitor][49]: Start monitoring
34.880773 [D][1][Server][441]: server directed query on collection admin.$cmd on server localhost:65013
35.192658 [D][8][Monitor][203]: Weighted mean RTT: 29.785839 (ms) for server localhost:65013
35.204976 [I][1][Client][276]: Client topology is TT-Unknown
35.206572 [I][1][Client][276]: Client topology is TT-Single
35.210277 [D][1][Database][62]: run command ping
35.212104 [D][1][Client][500]: Searched for 0.8115867558140858 ms
35.212872 [D][1][Client][503]: Server 'localhost:65013' selected
1st run:   0.3728209
35.223682 [D][1][Database][62]: run command ping
35.224926 [D][1][Client][500]: Searched for 0.45060024281253264 ms
35.225674 [D][1][Client][503]: Server 'localhost:65013' selected
1st rerun: 0.387305
35.237930 [W][1][Client][59]: User client object still defined, will be cleaned first
35.242407 [D][1][Client][688]: server 'localhost:65013' destroyed after 0.003765 sec
35.243238 [D][1][Client][699]: Client destroyed after 0.0046391 sec
35.244628 [D][1][Uri][112]: parse mongodb://localhost:65013/
35.246200 [D][1][Client][105]: Found 1 servers in uri
35.246800 [D][1][Client][109]: todo: localhost:65013
35.252433 [D][1][Server][441]: server directed query on collection admin.$cmd on server localhost:65013
35.273011 [I][1][Client][276]: Client topology is TT-Unknown
35.283166 [I][1][Client][276]: Client topology is TT-Single
35.285424 [D][1][Database][62]: run command ping
35.286606 [D][1][Client][500]: Searched for 0.3175902112072325 ms
35.287062 [D][1][Client][503]: Server 'localhost:65013' selected
2nd run:   0.0562678

I am curious if you find better results with this. I must however warn you that I am not sure if the topology is build properly for all cases. Also I've never tested against shard servers and arbiters. Also the rewrite still must be done to follow the documents of David.

P.s. prove6 comes with package App::Prove6

[MARTIMM]

did not mean to close it, sorry....

[samebchase]

Now it takes around 4 seconds which is fine for my needs, and after all your efforts it can only get faster from here. 😎

I did get a test failure on Linux while installing, so I skipped the tests. Attaching the log output for reference.

===> Building: MongoDB:ver<0.43.9>
[MongoDB] Download server version 4.0.5
[MongoDB] /home/vagrant/src/mongo-perl6-driver/t/Travis-ci/install-mongodb.sh: 18: [: x: unexpected operator
[MongoDB] /home/vagrant/src/mongo-perl6-driver/t/Travis-ci/install-mongodb.sh: 23: cd: can't cd to /t/Travis-ci
[MongoDB] /home/vagrant/src/mongo-perl6-driver/t/Travis-ci/install-mongodb.sh: 18: [: x: unexpected operator
[MongoDB] /home/vagrant/src/mongo-perl6-driver/t/Travis-ci/install-mongodb.sh: 23: cd: can't cd to /t/Travis-ci
[MongoDB] Download server version 4.0.18
===> Building [OK] for MongoDB:ver<0.43.9>
===> Testing: MongoDB:ver<0.43.9>
[MongoDB]
[MongoDB] --------------------------------------------------------------------------------
[MongoDB] 2020-05-19 03:53
[MongoDB] 35.902719 [I][1][ ][11]: Test /home/vagrant/src/mongo-perl6-driver/t/098-mk-sandbox.t start
[MongoDB] The spawned command '/home/vagrant/src/mongo-perl6-driver/t/Travis-ci/4.0.18/mongod --dbpath "/home/vagrant/src/mongo-perl6-driver/Sandbox/Server-s
1/m.data" --pidfilepath "/home/vagrant/src/mongo-perl6-driver/Sandbox/Server-s1/m.pid" --logpath "/home/vagrant/src/mongo-perl6-driver/Sandbox/Server-s1/m.lo
g" --nojournal --port "65014" --verbose "vv" --fork' exited unsuccessfully (exit code: 127, signal: 0)
[MongoDB]   in sub fatal-message at /home/vagrant/src/mongo-perl6-driver/lib/MongoDB/Log.pm6 (MongoDB::Log) line 301
[MongoDB]   in block  at /home/vagrant/src/mongo-perl6-driver/lib/MongoDB/Server/Control.pm6 (MongoDB::Server::Control) line 84
[MongoDB]   in any  at /home/vagrant/src/mongo-perl6-driver/lib/MongoDB/Server/Control.pm6 (MongoDB::Server::Control) line 82
[MongoDB]   in method start-mongod at /home/vagrant/src/mongo-perl6-driver/lib/MongoDB/Server/Control.pm6 (MongoDB::Server::Control) line 80
[MongoDB]   in block <unit> at t/099-start-servers.t line 19
[MongoDB] Cannot look up attributes in a BSON::Document type object
[MongoDB]   in method find-key at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA
6F1A1424A58 (BSON::Document) line 273
[MongoDB]   in method AT-KEY at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA6F
1A1424A58 (BSON::Document) line 288
[MongoDB]   in method server-version at /home/vagrant/src/mongo-perl6-driver/t/Test-support.pm6 (Test-support) line 398
[MongoDB]   in block <unit> at t/200-Database.t line 28
[MongoDB] Cannot look up attributes in a BSON::Document type object
[MongoDB]   in method find-key at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA
6F1A1424A58 (BSON::Document) line 273
[MongoDB]   in method AT-KEY at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA6F
1A1424A58 (BSON::Document) line 288
[MongoDB]   in block <unit> at t/300-Collection.t line 49
[MongoDB] Cannot look up attributes in a BSON::Document type object
[MongoDB]   in method find-key at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA
6F1A1424A58 (BSON::Document) line 273
[MongoDB]   in method AT-KEY at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA6F
1A1424A58 (BSON::Document) line 288
[MongoDB]   in block <unit> at t/301-Collection.t line 44
[MongoDB] Cannot look up attributes in a BSON::Document type object
[MongoDB]   in method find-key at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA
6F1A1424A58 (BSON::Document) line 273
[MongoDB]   in method AT-KEY at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA6F
1A1424A58 (BSON::Document) line 288
[MongoDB]   in method server-version at /home/vagrant/src/mongo-perl6-driver/t/Test-support.pm6 (Test-support) line 398
[MongoDB]   in block <unit> at t/400-run-command.t line 29
[MongoDB] Cannot look up attributes in a BSON::Document type object
[MongoDB]   in method find-key at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA
6F1A1424A58 (BSON::Document) line 273
[MongoDB]   in method AT-KEY at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA6F
1A1424A58 (BSON::Document) line 288
[MongoDB]   in block <unit> at t/401-rc-query-write.t line 54
[MongoDB] Cannot look up attributes in a BSON::Document type object
[MongoDB]   in method find-key at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA
6F1A1424A58 (BSON::Document) line 273
[MongoDB]   in method AT-KEY at /home/vagrant/.rakudobrew/versions/moar-master-master-master/install/share/perl6/site/sources/6F91AD0E8CD10642A34EEDFFAABCA6F
1A1424A58 (BSON::Document) line 288
[MongoDB]   in method server-version at /home/vagrant/src/mongo-perl6-driver/t/Test-support.pm6 (Test-support) line 398
[MongoDB]   in block <unit> at t/450-find.t line 32
===> Testing [FAIL]: MongoDB:ver<0.43.9>
Aborting due to test failure: MongoDB:ver<0.43.9> (use --force-test to override)

[JJ]

Same error (or whereabouts) here. Also, taking a long time to test...

[MARTIMM]

Hi Juan, Below is an installation of version 0.43.8. This is still the slow version starting this issue... Are you also on a single core system? I believe that is the main problem of its slowness.

> time zef install MongoDB
===> Searching for: MongoDB
===> Building: MongoDB:ver<0.43.8>:api<0>
===> Building [OK] for MongoDB:ver<0.43.8>:api<0>
===> Testing: MongoDB:ver<0.43.8>:api<0>
[MongoDB] # Running tests for server version 3.6.9
[MongoDB] # Running tests for server version 3.6.9
[MongoDB] # Running tests for server version 3.6.9
[MongoDB] # Running tests for server version 3.6.9
[MongoDB] # Running tests for server version 3.6.9
[MongoDB] # Running tests for server version 3.6.9
===> Testing [OK] for MongoDB:ver<0.43.8>:api<0>
===> Installing: MongoDB:ver<0.43.8>:api<0>

4 bin/ scripts [stop-servers.pl6 mongodb-accounting.pl6 start-servers.pl6 make-replicaset.pl6] installed to:
/home/Data/root-opt/Raku/rakudo/install/share/perl6/site/bin
112.004u 3.652s 2:10.37 88.7%   0+0k 185504+126720io 4pf+0w

I haven't yet moved the code into the master branch because I was a bit unsure if that change was completely correct. In the meantime, I started working on rewriting a few modules to follow the documents which David mentioned above more closely.

The errors from installing come from Build.pl6 which uses a shell script (sh). A remark from someone was that it might be caused by a symbolic link to a bash program on certain systems causing these errors. That is changed too but not yet published. Perhaps it is time to do so and taking the risk that something might go wrong.

Installing my local version (0.43.10) is faster, perhaps I should have a go with it.

> time zef install .
===> Building: MongoDB:ver<0.43.10>
[MongoDB] MongoDB server version 4.0.5 already downloaded
[MongoDB] MongoDB server version 4.0.18 already downloaded
===> Building [OK] for MongoDB:ver<0.43.10>
===> Testing: MongoDB:ver<0.43.10>
[MongoDB] 
[MongoDB] --------------------------------------------------------------------------------
[MongoDB] 2020-05-28 12:40
[MongoDB] 18.023294 [I][1][ ][11]: Test /home/marcel/Languages/Raku/Projects/mongo-perl6-driver/t/098-mk-sandbox.t start
===> Testing [OK] for MongoDB:ver<0.43.10>
===> Installing: MongoDB:ver<0.43.10>

4 bin/ scripts [start-servers.pl6 stop-servers.pl6 mongodb-accounting.pl6 make-replicaset.pl6] installed to:
/home/Data/root-opt/Raku/rakudo/install/share/perl6/site/bin
69.579u 3.087s 1:24.99 85.4%    0+0k 63704+8536io 240pf+0w

[samebchase]

Hey @MARTIMM, great to hear that you are working on the library based on the documents that David linked. 😎

[MARTIMM]

had some troubles merging branches. I've cut off the master branch and used the branch were I was working on and renamed it as master. Later I'll check whatever I did before in master. But now I've published version 0.43.10.2. The tests were ok on Travis.

[Zer0-Tolerance]

My two cents the snippet provided run in 1.77 secs using version 0.43.15 and MongoDB 3.6 on OS X 10.15.

@MARTIMM Keep up the good work, I'm also approving my Raku skill but we really need a decent MongoDB driver but hopefully @xdg can help :)

[MARTIMM]

@Zer0-Tolerance: That's nice to hear, I think that it cannot go much faster, but w'll see, miracles happen.

At the moment I've been working on the Gnome::* packages which is quite huge. This will be continued for a while because the mongodb driver is in a workable state. Although some changes are needed, the api of the methods will not change much as far as I can see.