I have a view in which I run 29 queries to my database. The database queries execute in around ~2 secs - which is perfectly fine - but my entire request takes 9 seconds accourding to the Debug toolbar. When I look at the Log Messages I see that the step from "yii\base\Controller::runAction" to actually starting to run the queries takes almost 7 seconds. What happens during this time? If I then reload the same view the same step takes like ~200 ms.
The actual view then renders in like 5 ms.
1 15:08:47.119 trace yii\base\Application::bootstrap Bootstrap with yii\log\Dispatcher
2 15:08:47.119 trace yii\base\Module::getModule Loading module: debug
3 15:08:47.123 trace yii\base\Application::bootstrap Bootstrap with yii\debug\Module::bootstrap()
4 15:08:47.126 trace yii\web\UrlManager::parseRequest No matching URL rules. Using default URL parsing logic.
5 15:08:47.126 trace yii\web\Application::handleRequest Route requested: 'rooms/pickup-table'
6 15:08:47.128 trace yii\base\Controller::runAction Route to run: rooms/pickup-table
7 15:08:54.192 info yii\web\Session::open Session started
/var/www/domain.com/app/components/AccessRule.php (43)
Thanks for all the help you guys can give me in understanding this.
There are lots of things that might be happening, some related to yii (log setup etc) and others that might be related to your actual box and what else is happening. I can’t think of anything that would add that much time but you could use task manager/top to find out what is eating CPU or disk at that point.
It is also possible that the database emulation for your queries is taking a long time, although this will be cached for future use, which is why subsequent calls are quicker. You can disable emulatePrepare in the database config if you want to see if that makes a difference http://www.yiiframework.com/doc-2.0/yii-db-connection.html#$emulatePrepare-detail.
Thanks for the replies guys. Below you have my "Performance Profiling" and "Log messages" trace log. As you can see the database queries only take up ~2-3 seconds and then something else takes ~4-5 seconds. Any idea how I can investigate this further?
Performance Profiling
Total processing time: 9,419 ms; Peak memory: 10.0 MB.
1 18:01:21.881 2.8 ms yii\db\Command::query
2 18:01:21.674 206.6 ms yii\db\Command::query
3 18:01:21.476 197.4 ms yii\db\Command::query
4 18:01:21.475 0.4 ms yii\db\Command::query
5 18:01:21.440 4.8 ms yii\db\Command::query
6 18:01:20.830 607.7 ms yii\db\Command::query
7 18:01:20.303 525.3 ms yii\db\Command::query
8 18:01:19.795 508.1 ms yii\db\Command::query
9 18:01:19.794 0.4 ms yii\db\Command::query
10 18:01:18.725 1064.6 ms yii\db\Command::query
11 18:01:18.720 0.4 ms yii\db\Command::query
12 18:01:18.719 0.7 ms yii\db\Command::query
13 18:01:18.719 0.5 ms yii\db\Command::query
14 18:01:18.717 0.4 ms yii\db\Command::query
15 18:01:18.716 0.7 ms yii\db\Command::query
16 18:01:18.715 0.4 ms yii\db\Command::query
17 18:01:18.714 0.4 ms yii\db\Command::query
18 18:01:18.713 0.7 ms yii\db\Command::query
19 18:01:18.713 0.4 ms yii\db\Command::query
20 18:01:18.712 0.4 ms yii\db\Command::query
21 18:01:18.711 0.3 ms yii\db\Command::query
22 18:01:18.711 0.3 ms yii\db\Command::query
23 18:01:18.710 0.3 ms yii\db\Command::query
24 18:01:18.709 0.4 ms yii\db\Command::query
25 18:01:18.708 0.4 ms yii\db\Command::query
26 18:01:18.708 0.4 ms yii\db\Command::query
27 18:01:18.704 0.5 ms yii\db\Command::query
28 18:01:18.702 1.0 ms yii\db\Command::query
29 18:01:18.700 0.4 ms yii\db\Command::query
30 18:01:18.696 3.9 ms yii\db\Connection::open Opening DB connection
Log messages
1 18:01:12.508 trace yii\base\Application::bootstrap Bootstrap with yii\log\Dispatcher
2 18:01:12.508 trace yii\base\Module::getModule Loading module: debug
3 18:01:12.512 trace yii\base\Application::bootstrap Bootstrap with yii\debug\Module::bootstrap()
4 18:01:12.515 trace yii\web\UrlManager::parseRequest No matching URL rules. Using default URL parsing logic.
5 18:01:12.515 trace yii\web\Application::handleRequest Route requested: 'rooms/pickup-table'
6 18:01:12.517 trace yii\base\Controller::runAction Route to run: rooms/pickup-table
7 18:01:18.684 info yii\web\Session::open Session started
8 18:01:18.696 info yii\db\Command::query
9 18:01:18.696 info yii\db\Connection::open Opening DB connection
10 18:01:18.702 info yii\db\Command::query
11 18:01:18.704 info yii\db\Command::query
12 18:01:18.708 info yii\db\Command::query
13 18:01:18.708 info yii\db\Command::query
14 18:01:18.709 trace yii\rbac\DbManager::checkAccessRecursive Checking role: user
15 18:01:18.709 info yii\db\Command::query
16 18:01:18.710 info yii\db\Command::query
17 18:01:18.710 info yii\db\Command::query
18 18:01:18.711 trace yii\rbac\DbManager::checkAccessRecursive
19 18:01:18.711 info yii\db\Command::query
20 18:01:18.712 trace yii\base\InlineAction::runWithParams
21 18:01:18.712 info yii\db\Command::query
22 18:01:18.713 info yii\db\Command::query
23 18:01:18.713 info yii\db\Command::query
24 18:01:18.714 info yii\db\Command::query
25 18:01:18.715 info yii\db\Command::query
26 18:01:18.716 info yii\db\Command::query
27 18:01:18.717 info yii\db\Command::query
28 18:01:18.718 info yii\db\Command::query
29 18:01:18.719 info yii\db\Command::query
30 18:01:18.720 info yii\db\Command::query
31 18:01:18.725 info yii\db\Command::query
32 18:01:19.794 info yii\db\Command::query
33 18:01:19.795 info yii\db\Command::query
34 18:01:20.303 info yii\db\Command::query
35 18:01:20.830 info yii\db\Command::query
36 18:01:21.440 info yii\db\Command::query
37 18:01:21.475 info yii\db\Command::query
38 18:01:21.476 info yii\db\Command::query
39 18:01:21.674 info yii\db\Command::query
40 18:01:21.881 info yii\db\Command::query
41 18:01:21.885 trace yii\base\View::renderFile Rendering view file:
42 18:01:21.904 trace yii\base\View::renderFile Rendering view file:
If I re-run the same view again the Log messages look like this:
1 18:09:20.811 trace yii\base\Application::bootstrap Bootstrap with yii\log\Dispatcher
2 18:09:20.811 trace yii\base\Module::getModule Loading module: debug
3 18:09:20.815 trace yii\base\Application::bootstrap Bootstrap with yii\debug\Module::bootstrap()
4 18:09:20.818 trace yii\web\UrlManager::parseRequest No matching URL rules. Using default URL parsing logic.
5 18:09:20.818 trace yii\web\Application::handleRequest Route requested: 'rooms/pickup-table'
6 18:09:20.820 trace yii\base\Controller::runAction Route to run: rooms/pickup-table
7 18:09:20.825 info yii\web\Session::open Session started
8 18:09:20.837 info yii\db\Command::query
9 18:09:20.837 info yii\db\Connection::open Opening DB connection
10 18:09:20.841 info yii\db\Command::query
...............
41 18:09:20.911 trace yii\base\View::renderFile Rendering view file:
42 18:09:20.929 trace yii\base\View::renderFile Rendering view file:
I’ve removed all the database queries and server paths for security reasons.
Silly question but does anything else happen inside the action method before you query the database?
Also, runAction calls beforeAction on ALL attached modules and the controller itself, which will fire any events attached to beforeAction. All kinds of things could happen at that point, translations could be loaded (and then cached), the database connection could be opened if it has gone to sleep etc.
The only sure fire way to test is either to add more trace calls (you could add them into the Yii code temporarily and remove them afterwards) or get your debugger to work so you can step through the code and see what is slow. Remember, when debugging, you are probably moving slower through the code so you might not easily catch the slowness. It would be better to set breakpoints and press Go to keep narrowing down which bit the problem is.
You could also try disabling any modules you are using temporarily to see if they are the problem.
Fault-finding is mostly a process of elimination, logging and sub-dividing.
Thanks for the reply Lukos. I guess I’ll have to dive in with some custom trace-calls then to see what is happening. Wanted to ask to see if there was any obvious thing it could be.
I’m not using any custom models and inside the Controller nothing happens then running the DB-queries through yii->db->createCommand before returning it to the View.
My best own guess is that something is being cached, but I have no idea what (since any calls afterwards takes X ms).
