+5 seconds execution time / Cause?

[eluser]popovich[/eluser]
Cheers,

I am having a problem here and I am pretty much lost.

The local server added 5 seconds to the execution time just because... I don't know what happened. The server I am running locally is a WAMP5 (PHP 5.2.4, Apache 2.2.4, mySQL 5.0.45-community-nt) on Win 7, 64-bit. The staging server is a hosted server and is running a Linux with a PHP 5.2.11, mySQL 5.1.45.

The problem occurs only on the Windows webserver. I have copied the files over to the staging server and it is running the scripts as expected (within 0.5 seconds). The Windows box needs over 5 seconds to run the scripts now. The latest thing I was working on was fixing a mySQL statement, which now includes couple of inner selects and counts. PMA still needs only 0.100 seconds to execute that statement, but CI on Windows thinks otherwise.

Here is an excerpt of the log file from toda. The first excerpt is the normal behavior:

Code:

DEBUG - 2010-10-13 15:54:04 --> Config Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Hooks Class Initialized
DEBUG - 2010-10-13 15:54:04 --> URI Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Router Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Output Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Input Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Global POST and COOKIE data sanitized
DEBUG - 2010-10-13 15:54:04 --> Language Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Loader Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Helper loaded: url_helper
DEBUG - 2010-10-13 15:54:04 --> Helper loaded: cookie_helper
DEBUG - 2010-10-13 15:54:04 --> Helper loaded: markdown_helper
DEBUG - 2010-10-13 15:54:04 --> Database Driver Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Session Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Helper loaded: string_helper
DEBUG - 2010-10-13 15:54:04 --> Session routines successfully run
DEBUG - 2010-10-13 15:54:04 --> Controller Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Model Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Model Class Initialized
DEBUG - 2010-10-13 15:54:04 --> User Agent Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Model Class Initialized
DEBUG - 2010-10-13 15:54:04 --> Helper loaded: spec_helper
DEBUG - 2010-10-13 15:54:04 --> Helper loaded: typography_helper
DEBUG - 2010-10-13 15:54:04 --> Helper loaded: modules_helper
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/modules/mv_pos_display.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/modules/mv_geo_browser.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/modules/mv_geo_list.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/meta.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/stylesheets.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/scripts.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/custom_jquery.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/analytics.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/logo.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/navi.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/navi.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/navi.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/navi.php
DEBUG - 2010-10-13 15:54:04 --> File loaded: J:\ATLAS\*\WWW_New/system/application/views/layouts/two_columns_alt_view.php
DEBUG - 2010-10-13 15:54:04 --> Final output sent to browser
DEBUG - 2010-10-13 15:54:04 --> Total execution time: 0.3951

......

[eluser]popovich[/eluser]
..., the second excerpt is the abnormal behavior:

Code:

DEBUG - 2010-10-13 18:03:17 --> Config Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Hooks Class Initialized
DEBUG - 2010-10-13 18:03:17 --> URI Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Router Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Output Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Input Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Global POST and COOKIE data sanitized
DEBUG - 2010-10-13 18:03:17 --> Language Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Loader Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Helper loaded: url_helper
DEBUG - 2010-10-13 18:03:17 --> Helper loaded: cookie_helper
DEBUG - 2010-10-13 18:03:17 --> Helper loaded: markdown_helper
DEBUG - 2010-10-13 18:03:17 --> Database Driver Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Session Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Helper loaded: string_helper
DEBUG - 2010-10-13 18:03:17 --> Session routines successfully run
DEBUG - 2010-10-13 18:03:17 --> Controller Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Model Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Model Class Initialized
DEBUG - 2010-10-13 18:03:17 --> User Agent Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Model Class Initialized
DEBUG - 2010-10-13 18:03:17 --> Helper loaded: spec_helper
DEBUG - 2010-10-13 18:03:17 --> Helper loaded: typography_helper
DEBUG - 2010-10-13 18:03:17 --> Helper loaded: modules_helper
DEBUG - 2010-10-13 18:03:17 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/modules/mv_press_viewer.php
DEBUG - 2010-10-13 18:03:18 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/modules/mv_latest_news.php
DEBUG - 2010-10-13 18:03:18 --> File loaded: J:\ATLAS\**WWW_New/system/application/views/modules/mv_geo_list.php
DEBUG - 2010-10-13 18:03:18 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/meta.php
DEBUG - 2010-10-13 18:03:18 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/stylesheets.php
DEBUG - 2010-10-13 18:03:18 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/scripts.php
DEBUG - 2010-10-13 18:03:19 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/custom_jquery.php
DEBUG - 2010-10-13 18:03:20 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/analytics.php
DEBUG - 2010-10-13 18:03:20 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/logo.php
DEBUG - 2010-10-13 18:03:21 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/navi.php
DEBUG - 2010-10-13 18:03:21 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/navi.php
DEBUG - 2010-10-13 18:03:23 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/navi.php
DEBUG - 2010-10-13 18:03:23 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/partials/navi.php
DEBUG - 2010-10-13 18:03:23 --> File loaded: J:\ATLAS\**\WWW_New/system/application/views/layouts/two_columns_view.php
DEBUG - 2010-10-13 18:03:23 --> Final output sent to browser
DEBUG - 2010-10-13 18:03:23 --> Total execution time: 5.2286

Here are the two mysql statements, the second one being the new one. Switching between the old and the new statements now doesn't affect the execution time at all.

Code:

$q = "SELECT c.do_trigger, l.label
                FROM pos_country_label as l
                LEFT JOIN pos_country as c
                    ON l.country_id = c.id
                WHERE l.lang_id = ".$this->CI->GLO['user_lang_id']."
                    AND c.published = 'yes'
                ORDER BY l.label ASC;";

( the new statement )

Code:

$q = "SELECT c.do_trigger,
                    l.label,
                    ( SELECT COUNT(*) FROM pos_details pos WHERE pos.published = 'yes' AND pos.city_id = pc.id ) AS pos_on,
                    ( SELECT COUNT(*) FROM pos_city pc WHERE pc.published = 'yes' AND pc.country_id = c.id) AS city_on
            FROM pos_country_label AS l,
                    pos_country AS c,
                    pos_city AS pc                
            WHERE l.lang_id =".$this->CI->GLO['user_lang_id']."
                AND c.published =  'yes'
                AND l.country_id = c.id
                AND pc.country_id = c.id
            GROUP BY c.id
            ORDER BY l.label ASC
            LIMIT 0,30;";

OK, I have "optimize"d and"analyze"d couple of tables, added two index columns to the two of the tables and later removed the columns. The speed just went down since running the updated sql-statement for the first time and never came back. Every other script is running wonderfully on the same Windows box (PMA, the CMS' backend, whatever) and the Linux server also doesn't have any problems.

What could be the cause?

[eluser]popovich[/eluser]
Here is a quick update, which makes the whole situation even more weird.
I have noticed, that the execution slows down just after loading a view called "partials/scripts.php", which has nothing in it except for this:

Code:

<!--[if lt IE 7.]>
            <script defer type="text/javascript" src="styles/pngfix.js"></script>
            <![endif]-->
            
            <script src="{baseurl}scripts/jquery-1.4.2.min.js" type="text/javascript"></script>
            <script src="{baseurl}scripts/jquery-ui-1.8.2.custom.min.js" type="text/javascript"></script>
            <script src="{baseurl}scripts/sizzle.js" type="text/javascript"></script>
            <script src="{baseurl}scripts/cufon-yui.js" type="text/javascript"></script>
            <script src="{baseurl}scripts/cufonts/Charis_400-Charis_700.font.js" type="text/javascript"></script>
            <script src="{baseurl}scripts/cufonts/Univers_500.font.js" type="text/javascript"></script>

I have not touched these files since June or July. I have checked them and haven't found any malware includes, like "try ()", as it could have be the case for a JS-trojan or something.

If I exclude this very view file from parsing, everything flies again. How come?...

[eluser]popovich[/eluser]
Forget it. Everything back to normal without anything being done from my side. I was just reading logs.
Thanks, Windows 7!

To admins: can you please delete this thread? Thanks!

[eluser]cahva[/eluser]
Nice conversation with yourself

In the future use some profiling to know what causes slowdown:
1. use $this->output->enable_profiler() to see how long it took for database and controllers
2. If using Firefox install firebug check the "Net" tab to see how long it took for the requests and if you use chrome, theres developer tools to see the same

[eluser]popovich[/eluser]
There are two forums (CI and YAY), where such things happen to me and I avoid posting there anything at all, as the problem normally is being solved while I am posting. Today, I thought, was an exception. Here we go...

Thanks for the tip on profiler. Still, I find it absolutely inexplicable why all this happened... And that's already after rebooting both machines (I thought it was a LAN problem).

Cheers.