request latency

[EranGabber]

The elapsed time of the collector fetching data for the first time from a cluster is more than 10 seconds, which seems like an eternity.

Note that the collector should use parallelism for extract the data, so this may be a bug somewhere.

[EranGabber]

Elapsed time on a test cluster provided by Jack:

$ time curl http://xxx.xxx.xxx.xxx:5555/cluster | wc
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 8975k 100 8975k 0 0 1394k 0 0:00:06 0:00:06 --:--:-- 2119k
132893 153118 9191413

real 0m6.461s
user 0m0.154s
sys 0m0.038s

[EranGabber]

Interestingly, two containers in the said cluster contain an extra long list of ExecIDs (about 100,000 entries in each). It should be eliminated by the cluster-insight minion. This may explain some of the increase in the elapsed time.

[supriyagarg]

Also, both these containers are the skydns containers. The same that had the extra long ExecIDs in the cassandra cluster projects.

[EranGabber]

Before deleting the values of ExecIDs by the cluster-insight minion:
Note that the 2nd request is immediately following the first request.
The target cluster is running the Guesbook app.
$ time curl http://xxx.xxx.xxx.xxx:5555/cluster | wc
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 8462k 100 8462k 0 0 1007k 0 0:00:08 0:00:08 --:--:-- 2019k
115698 123192 8665329

real 0m8.405s
user 0m0.255s
sys 0m0.072s
$ time curl http://xxx.xxx.xxx.xxx:5555/cluster | wc
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 8462k 100 8462k 0 0 1583k 0 0:00:05 0:00:05 --:--:-- 2043k
115699 123193 8665408

real 0m5.354s
user 0m0.234s
sys 0m0.100s

[EranGabber]

After omitting the value of ExecIDs by the cluster-insight minions:
Note that the 2nd request is immediately following the first request.
The target cluster is running the Guesbook app.

$ time curl http://xxx.xxx.xxx.xxx:5555/cluster | wc
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 403k 100 403k 0 0 108k 0 0:00:03 0:00:03 --:--:-- 108k
11352 18998 413344

real 0m3.726s
user 0m0.022s
sys 0m0.004s
$ time curl http://xxx.xxx.xxx.xxx:5555/cluster | wc
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 403k 100 403k 0 0 1159k 0 --:--:-- --:--:-- --:--:-- 1163k
11352 18998 413344

real 0m0.358s
user 0m0.012s
sys 0m0.013s

*** important observations ***
The amount of data produced by accessing the /cluster endpoint was reduced from 8462KB to 403KB.
The elapsed time for a cold cache was reduced from 8.4 seconds to 3.7 seconds.

[EranGabber]

It takes about 1 second for Docker to return the details of this container. This time varies from 0.6 seconds to 1.1 seconds. Note that the "docker inspect" command returns over 8 MB of data. Caching at the cluster-insight minion should eliminate the long latency of reading the raw data from Docker.

$ time sudo docker inspect 5e9a552724da | wc
109457 109561 8312039

real 0m0.594s
user 0m0.268s
sys 0m0.028s
$ time sudo docker inspect 5e9a552724da | wc
109458 109562 8312115

real 0m1.104s
user 0m0.248s
sys 0m0.020s
$ time sudo docker inspect 5e9a552724da | wc
109458 109562 8312115

real 0m0.949s
user 0m0.244s
sys 0m0.016s
$ time sudo docker inspect 5e9a552724da | wc
109458 109562 8312115

real 0m0.648s
user 0m0.272s
sys 0m0.008s

[EranGabber]

Current implementation:
(a) the minion keep a warm cache of all container information, which is initialized at start time.
Any cache miss will also populate the cache. The data is kept in the cache for one hour.
(b) the value of the ExecIDs attribute in all containers is removed by the minions, because it is often a very large list of hex values (more than 8MB of text).
(c) I still need to refresh the cache every hour to keep is warm.

The performance now on a cluster running the Guestbook app.
Cold collector cache:
$ time curl http://xxx.xxx.xxx.xxx:5555/cluster | wc
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 160 100 160 0 0 399 0 --:--:-- --:--:-- --:--:-- 400
4 16 160

real 0m0.532s
user 0m0.003s
sys 0m0.006s

Hot collector cache:
$ time curl http://xxx.xxx.xxx.xxx:5555/cluster | wc
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 160 100 160 0 0 1282 0 --:--:-- --:--:-- --:--:-- 1280
4 16 160

real 0m0.131s
user 0m0.000s
sys 0m0.008s

[EranGabber]

still need to do:

1. try to increase the number of worker threads in the master.
2. write a unit test for docker_proxy.py

[EranGabber]

I will close this issue after trying to increase the number of worker threads and write a unit test.