Multi-VM Performance Tuning

Events happening in the community are now at Drupal community events on www.drupal.org.
repoman's picture

Our production environment takes roughly 7 secs to fully render, of which it doesn't start rending until 3.4 secs. So rather than attempting all the great information listed here we built an identical Staging environment with the same exact setup as production. I will include our AB stats along with all the configuration information in hope that some of you might be able to point me in the right direction.

Any help would be greatly appreciated.

Server Layout (All RH 5.6 servers) & All running on Fibre SAN

DIRTY DMZ

Proxy - Resides on a DMZ on the least secure VLAN of our FW.
* Varnish & Pound - Varnish for http and Pound for SSL relaying to our web heads
* 2 cores
* 2GB RAM
SOLR - Purely for Search indexes
* Apache Solr
* 2 cores
* 2GB RAM


SAFE DMZ

Web Head
* Pressflow w/APC and Memcache enabled. I also installed the CacheRouter module, however, I cannot tell if it is working properly.
* Apache 2.2.3, PHP5.2.17
* 4 cores
* 2GB RAM


DB Server
* MySQL 5.0.77
* 4 cores
* 4GB RAM


AB Test from Web Head:

ab -A -n 2000 -c 10 http://staging.xxxxxx.org/
This is ApacheBench, Version 2.0.40-dev <$Revision: 1.146 $> apache-2.0
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Copyright 2006 The Apache Software Foundation, http://www.apache.org/

Benchmarking staging.xxxxxxx.org (be patient)
Completed 200 requests
Completed 400 requests
Completed 600 requests
Completed 800 requests
Completed 1000 requests
Completed 1200 requests
Completed 1400 requests
Completed 1600 requests
Completed 1800 requests
Finished 2000 requests

Server Software: Apache
Server Hostname: staging.xxxxxxxx.org
Server Port: 80

Document Path: /
Document Length: 51227 bytes

Concurrency Level: 10
Time taken for tests: 767.664779 seconds
Complete requests: 2000
Failed requests: 0
Write errors: 0
Total transferred: 103328000 bytes
HTML transferred: 102454000 bytes
Requests per second: 2.61 [#/sec] (mean)
Time per request: 3838.324 [ms] (mean)
Time per request: 383.832 [ms] (mean, across all concurrent requests)
Transfer rate: 131.45 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 1.5 0 43
Processing: 1997 3832 4263.8 2972 51331
Waiting: 1938 3757 4245.8 2910 51250
Total: 1997 3833 4263.8 2972 51331

Percentage of the requests served within a certain time (ms)
50% 2972
66% 3163
75% 3322
80% 3480
90% 4769
95% 6220
98% 17109
99% 29688
100% 51331 (longest request)

****** TOP - While AB was running *******

top - 15:15:55 up 12 days, 6:19, 2 users, load average: 14.78, 10.14, 4.97

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
26897 apache 16 0 171m 86m 6504 R 27.9 4.2 0:41.02 httpd
26900 apache 17 0 166m 80m 6336 R 40.8 4.0 0:58.27 httpd
26902 apache 18 0 171m 79m 5792 R 6.6 3.9 0:56.88 httpd
26866 apache 16 0 163m 77m 6504 S 0.0 3.8 0:48.62 httpd
26869 apache 16 0 162m 75m 5784 S 0.0 3.7 0:46.56 httpd
26870 apache 16 0 166m 72m 5972 S 0.0 3.6 0:47.56 httpd
26875 apache 15 0 156m 71m 6360 S 0.0 3.5 0:43.09 httpd
26893 apache 18 0 155m 70m 6608 R 21.2 3.5 0:55.39 httpd
26888 apache 17 0 154m 70m 6340 R 36.7 3.5 0:45.24 httpd
26868 apache 16 0 155m 70m 5872 S 0.0 3.5 0:46.81 httpd
26901 apache 16 0 154m 69m 5784 S 0.0 3.4 0:49.71 httpd
26892 apache 16 0 155m 68m 6360 S 0.0 3.4 0:43.59 httpd
26876 apache 18 0 142m 63m 6868 R 18.7 3.1 1:04.32 httpd
26874 apache 15 0 161m 61m 5780 S 0.0 3.0 0:43.95 httpd
26882 apache 16 0 137m 57m 6452 S 0.0 2.8 0:55.58 httpd
26898 apache 16 0 165m 54m 6360 S 3.5 2.7 0:40.80 httpd
26903 apache 16 0 162m 50m 5668 R 44.3 2.5 0:51.27 httpd
26889 apache 16 0 155m 49m 6572 S 0.0 2.5 0:51.53 httpd
26880 apache 17 0 125m 49m 6448 R 12.7 2.4 1:02.80 httpd
26904 apache 17 0 126m 48m 5788 R 46.2 2.4 0:55.72 httpd
26891 apache 16 0 157m 48m 6476 S 0.0 2.4 0:51.71 httpd
26886 apache 17 0 119m 45m 6432 R 16.1 2.2 0:45.71 httpd
26883 apache 15 0 120m 43m 6616 S 0.0 2.2 0:45.97 httpd
26879 apache 16 0 119m 43m 7168 S 0.0 2.2 0:46.45 httpd
26887 apache 16 0 119m 42m 6568 S 0.0 2.1 0:49.38 httpd
26867 apache 16 0 115m 40m 5908 S 0.0 2.0 0:48.33 httpd
26873 apache 15 0 110m 36m 7376 S 0.0 1.8 0:49.43 httpd
26890 apache 18 0 112m 36m 6344 R 0.0 1.8 1:00.11 httpd
26896 apache 15 0 110m 36m 7284 S 0.0 1.8 0:49.61 httpd
26899 apache 16 0 111m 36m 6520 S 0.0 1.8 0:48.72 httpd
26878 apache 16 0 110m 36m 6596 S 0.0 1.8 0:50.96 httpd
26877 apache 15 0 111m 35m 6436 S 0.0 1.8 0:51.67 httpd
26884 apache 16 0 111m 35m 6424 S 0.0 1.8 0:52.34 httpd
26871 apache 16 0 109m 35m 5736 S 0.0 1.7 0:40.85 httpd
26885 apache 16 0 109m 34m 5936 S 0.0 1.7 0:47.35 httpd
26894 apache 16 0 109m 34m 5904 S 8.9 1.7 0:49.96 httpd
26895 apache 15 0 108m 34m 6672 S 0.0 1.7 0:53.07 httpd
26881 apache 15 0 108m 34m 6596 S 0.0 1.7 1:03.08 httpd
26872 apache 16 0 108m 34m 6592 S 0.0 1.7 0:45.10 httpd
26905 apache 16 0 108m 33m 6340 S 0.0 1.7 0:50.93 httpd
26864 root 18 0 75856 8252 4996 S 0.0 0.4 0:00.49 httpd


CONFIGURATIONS

httpd.conf - prefork:

StartServers 40
MinSpareServers 40
MaxSpareServers 40
ServerLimit 40
MaxClients 40
MaxRequestsPerChild 50000


httpd.conf - worker:

StartServers 2
MaxClients 150
MinSpareThreads 25
MaxSpareThreads 75
ThreadsPerChild 25
MaxRequestsPerChild 0


Settings.php:

$conf['cache_inc'] = './sites/all/modules/contrib/cacherouter/cacherouter.inc';
$conf['cacherouter'] = array(
'default' => array(
'engine' => 'db',
'servers' => array(
'xxx.xxx.xxx.xxx:11211' => 'default',
'xxx.xxx.xxx.xxx:11212' => 'page',
'xxx.xxx.xxx.xxx:11213' => 'views',
'xxx.xxx.xxx.xxx:11214' => 'other',
),
'shared' => TRUE,
'prefix' => '',
'path' => 'sites/default/files/filecache',
'static' => FALSE,
'fast_cache' => TRUE,
),
);


PHP.ini

extension=apc.so
apc.enabled = 1
apc.shm_size = 48M
apc.rfc1867 = 1
; apc.stat = 0


/etc/php.d/memcache.ini

; Enable memcache extension module
extension=memcache.so

; Options for the memcache module

; Whether to transparently failover to other servers on errors
;memcache.allow_failover=1
; Defines how many servers to try when setting and getting data.
;memcache.max_failover_attempts=20
; Data will be transferred in chunks of this size
;memcache.chunk_size=8192
; The default TCP port number to use when connecting to the memcached server
;memcache.default_port=11211
; Hash function {crc32, fnv}
;memcache.hash_function=crc32
; Hash strategy {standard, consistent}
;memcache.hash_strategy=standard

; Options to use the memcache session handler

; Use memcache as a session handler
;session.save_handler=memcache
; Defines a comma separated of server urls to use for session storage
;session.save_path="tcp://localhost:11211?persistent=1&weight=1&timeout=1&retry_interval=15"


/etc/httpd/conf.d/pressflow.conf

ServerName staging.xxxxxxxxx.org
DocumentRoot /var/www/html/current/

AllowOverride All
AuthType Basic
AuthName Pressflow
AuthUserFile /etc/httpd/conf.d/pressflow.htpasswd
Require valid-user

Deny From All

    <IfModule mod_deflate.c>
            AddOutputFilterByType DEFLATE text/html text/plain text/xml text/css application/javascript application/x-javascript text/javascript application/xml application/rss+xml application/rss application/rss+atom
            DeflateCompressionLevel 8
    </IfModule>

    <IfModule mod_expires.c>
            ExpiresActive On
            ExpiresDefault "access plus 2 hours"
            ExpiresByType image/png "access plus 12 hours"
    </IfModule>

    Header unset ETag

   # Set special caching rules for PDF's
    <FilesMatch "\.(pdf|PDF)$">
        Header set Cache-Control "max-age=10, public, must-revalidate"
        Header unset Last-Modified
    </FilesMatch>

    Include /etc/httpd/conf.d/pressflow.redirects

    CustomLog /var/log/httpd/staging.xxxxxxxx.org-access_log combined
    ErrorLog /var/log/httpd/staging.xxxxxxxx.org-error_log

    FileETag none

    php_value       sendmail_from "noreply@xxxxxxxxxx.org"
    php_value error_reporting 22519

php_value date.timezone America/xxxxxxxxxxxxx

    php_value error_log /var/www/html/staging.xxxxxxxxxxxxx.org-php_log

I also have stats from the proxy, however, I figured to start on the Pressflow server first. Any ideas?

Comments

APC and page cache and memory_limit

stackpr's picture

If your site is complex (too many modules or templates), then your APC cache size might need to be larger. If it fills up too frequently, then you'll lose a lot of the benefit. Also, your ab suggests that you do not have page cache enabled -- at least not for your front page. Even with a late page cache in drupal, ab should do significantly better than that with your setup. If page caching is turned off, then you might not be seeing much benefit from your varnish boxes. Finally, what is your memory_limit in php? You're using quite a bit of memory-based caching, which is great. But then you're dividing what's left of your 2G across 40 processes. If you've installed enough modules to have to bump up the memory limit above ~32M, then you may need to add RAM or reduce the number of apache servers you launch so you don't have to use swap space.

You can rule these out quickly by increasing apc.shm_size to 128M, reducing the server count to 10, and then checking the headers on the front page to make sure Drupal is registering a cache hit.

Complex

repoman's picture

Our site is very complex and has well over 50 modules, of which 20-25 are custom.

Page cache is set to External as we have Varnish running on our Proxy.
* Min cache lifetime = 5min
* Page cache max lifetime = 15min

PHP.ini
* Memory_limit = 128M

Our production site only has Varnish configured, the rest we are trying to fine tune on our staging site, which we have secured via htpasswd. I will allow you guys to take look if you feel so inclined.
http://staging.uft.org
gdohiperf/drupalrox

Since this is staging we can tweak as we see fit before proceeding with promotion to Prod.

@repoman Since for some

dalin's picture

@repoman Since for some reason Drupal is sending a session cookie for all HTTP requests there really isn't any detective work that can be done from the outside. You'll need to dive into your code and see why sessions are being created.

--


Dave Hansen-Lange
Director of Technical Strategy, Advomatic.com
Pronouns: he/him/his

In order of importance

gchaix's picture

In order of importance:

  1. Something is setting a session cookie - that'll kill your caching. Varnish isn't doing any caching of the HTML. Figure out which module is setting the SESS cookie and find a way to either disable it or get it to not set the cookie. That's about 4s of the 7s load time right there.
  2. HTTP requests - you make a lot of them. Find a way to reduce the number of requests by using sprites or embedding images in CSS. You have 18 CSS images - convert them to sprites and/or CSS embeds and you more than halve the number of HTTP requests made.
  3. The total page load is a hefty 1061.9K. That's pretty darn big front page. I'd take a look at optimizing the images on the page.
  4. 400K of Flash on the front page? That's not going to do your pageload times much good, either. I'd take a look at alternative solutions to the SWF files if at all possible.

Some random observations

gchaix's picture

Definitely try a larger apc.shm_size.

Check the HTTP headers on the output content to see if it's being cached. If you haven't already, add some hit/miss stats to the headers in your Varnish VCL.

Do you have the the page cache set to something non-zero in "/admin/settings/performance"? If not, Varnish won't do a thing.

Your Varnish server RAM seems a bit small. 2G is not much room, depending on how complicated your site is.

Are you aggregating JS and CSS? Are you using css_emimage? If not, do. They all help a lot in reducing the number of HTTP requests.

css_emimage

mikeytown2's picture

If using css_emimage try Advanced CSS/JS Aggregation with the patch for it. Once I get an alt for jsmin+ setup and running I'll push out a 1.0 release of it. Checkout LABjs while your at it.

PROD vs. Staging

repoman's picture

PROD vs. Staging
Well our Production and Staging proxy/Varnish boxes are both running 2GB.

We have 88 Contrib modules & 33 Custom modules. A handful of which are enabled/disabled depending on Prod/Staging.

We are not using the 'css_emimage' module, however, I'll look into it.

Here is the pertinent section of our default.vcl file

    if (req.url ~ "^(/files/|/sites/all/themes|/sites/.*/files/|/sites/all/libraries)|favicon\.|\.(css|js)$") {
            if (req.url ~ "files/(imagecache|resize)/|\.php$") {
                    // Don't do this for imagecache, image_resize, or .php files since these can be full bootstraps.
            } else {
                    unset req.http.Cookie;
            }
    }

    // Remove has_js and Google Analytics __* cookies.
    set req.http.Cookie = regsuball(req.http.Cookie, "(^|;\s*)(__[a-z]+|has_js)=[^;]*", "");
    // Remove a ";" prefix, if present.
    set req.http.Cookie = regsub(req.http.Cookie, "^;\s*", "");
    // Remove empty cookies.
    if (req.http.Cookie ~ "^\s*$") {
            unset req.http.Cookie;
    }

    // Default request checks
    if (req.request != "GET" &&
            req.request != "HEAD" &&
            req.request != "PUT" &&
            req.request != "POST" &&
            req.request != "TRACE" &&
            req.request != "OPTIONS" &&
            req.request != "DELETE") {
            # Non-RFC2616 or CONNECT which is weird.
            return (pipe);
    }

    // We are not caching POST requests
    if (req.request != "GET" && req.request != "HEAD") {
            return (pipe);
    }

    remove req.http.X-Forwarded-For;
    set req.http.X-Forwarded-For = client.ip;
    // Enable grace period (varnish serves stale (but cacheable) objects while retriving object from backend) 
    // http://varnish-cache.org/wiki/Performance#VCLSetting
    set req.grace = 30s;

    // Cache things with these extensions
    if (req.url ~ "\.(js|css|jpg|jpeg|png|gif|gz|tgz|bz2|tbz|mp3|ogg|swf)$") {
            return (lookup);
    }

    // No varnish for install.php, update.php or cron.php
    if ( req.url ~ "^/(install.php|update.php|cron.php)" ) {
            return (pass);      
    }

    // Force lookup if the request is a no-cache request from the client
    if (req.http.Cache-Control ~ "no-cache") {
            return (pass);
    }

    // do not serve cached pages for logged in users
    if (req.http.Cookie ~ "SESS[a-f|0-9]+") {
            return (pass);
    }

    // Exclude dynamic pages
    if ( req.url ~ "^/(node/(.*)/(.*)|node/add/(.*)|user/(.*)|admin/(.*)|logout|upload/(.*)|flag/(.*))" ) {
            return (pass);
    }

    // Normalize the Accept-Encoding header
    // as per: http://varnish-cache.org/wiki/FAQ/Compression
    if (req.http.Accept-Encoding) {
            if (req.url ~ "\.(jpg|png|gif|gz|tgz|bz2|tbz|mp3|ogg)$$") {
            # No point in compressing these           
                    remove req.http.Accept-Encoding;
            } elsif (req.http.Accept-Encoding ~ "gzip") {
                    set req.http.Accept-Encoding = "gzip";
            } elsif (req.http.Accept-Encoding ~ "deflate") {
                    set req.http.Accept-Encoding = "deflate";
            } else {
                    # unkown algorithm
                    remove req.http.Accept-Encoding;
            }
    }

    // If we get here than try to serve from the cache
    return (lookup);

}

sub vcl_deliver {
if (obj.hits > 0) {
set resp.http.X-Varnish-Cache = "HIT";
set resp.http.X-Cache-Hits = obj.hits;
}
else {
set resp.http.X-Varnish-Cache = "MISS";
}
}

// this sets the hash which is used to match requests in the cache
// it is a combination of the url, host, cookie, and language
// any differences in these will result in different cache hits
// even for requests for the same url, this is to support i18n
sub vcl_hash {
set req.hash += req.url;
set req.hash += req.http.host;

    if (req.http.Cookie) {
            set req.hash += req.http.Cookie;
    }

    if( req.http.Accept-Language ) {
            set req.hash += req.http.Accept-Language;
    }
    return (hash);

}

sub vcl_error {
// Let's deliver a slightly more friedly error page.
// You can customize this as you wish.
set obj.http.Content-Type = "text/html; charset=utf-8";
synthetic {"
Only local images are allowed.
"};
return (deliver);
}

HITS & MISSES

repoman's picture

@gchaix On our staging environment we are using HITS and MISSES. It seems that the majority of what I see in the headers are HITS, with a few large images as MISSES. So I at a loss with some of you saying that Varnish is not working because of the SESSION. Am I 'MISSing' something? No PUN intended.

As far as RAM being used on the server for both environments, I don't see it hitting 2GB nor even close. We have Nagios monitoring everything and never hit a threshold. Is there something I should be looking for?

We have optimize CSS & JS enabled in 'Performance'

Yes technically you are

dalin's picture

Yes technically you are getting a HIT from Varnish. But because the HTTP request is unique to you (due to the cookie), it is only being served from the cache to you. When someone else comes along to the site they will have a different session cookie, hence there is nothing in the cache that matches the HTTP request, so Apache gets called in, and this new page also gets stored in Varnish. If this second person then views the same page again they will get a Varnish HIT.

--


Dave Hansen-Lange
Director of Technical Strategy, Advomatic.com
Pronouns: he/him/his

The clouds part and I see the sun!

repoman's picture

That explains why in my tests I see a miss then a hit for one browser and then the same for other browsers. I will take a close look into that autologout module. Thanks Dave!

Check out this article

gchaix's picture

Nate (quicksketch) posted a great article this week that covers a lot of the stuff you're looking at here. Its headline is about high availability and multiple servers (good stuff) but it also has a great bit about cookie handling:

http://www.lullabot.com/articles/varnish-multiple-web-servers-drupal

NewRelic

rjbrown99's picture

I suggest a 7 day trial of www.newrelic.com. You will immediately start to see where you are lagging (db, memcache, php) and specifically what functions are at play. It was immensely useful to me as a performance profiling tool and if you elect to pay for it the ongoing monitoring is also great.

EDIT: FWIW I have no relationship to the company at all, I just think it's a great tool.

Seconded

gchaix's picture

A trial account from New Relic would likely be quite helpful.

Thanks!!!!

repoman's picture

Since going to DrupalCon I got a 30 day eval of it and set it up on our Staging site, which I am considering running on our Prod site so I can really see the hits. Staging only shows hits when we are using it.

Our production environment

dalin's picture

Our production environment takes roughly 7 secs to fully render, of which it doesn't start rending until 3.4 secs.

It seems like you might be confusing front-end performance with back-end performance with scalability. AB only measures the time it takes to generate and serve the HTML page. That probably happens in <1 seconds for a miss of all caches, if the Varnish cache is hit then it's obviously much faster than that. The 7 seconds is a product of additional HTTP requests, JavaScript parsing and execution, ad frameworks, page rendering, etc.

In reviewing your site it looks like Varnish might not be working because something is setting session cookies even for anonymous users. Perhaps something is storing data in $_SESSION.

In looking at waterfall charts of your site there are a lot of static assets being downloaded, primarily images. HTTP requests is the number one contributor to slow page load times. Setting up a CDN should bring you the biggest gains by allowing the browser to download more resources in parallel. You would also benefit from setting up automated image compression, and creating image sprites.

--


Dave Hansen-Lange
Director of Technical Strategy, Advomatic.com
Pronouns: he/him/his

Varnish

repoman's picture

@Dalin - Varnish seems like a moving target for us. Some say it's working others say it's not. Our staging site has the HIT/MISS in the headers, while prod does not. Perhaps that will help. Instead of adding an additional expense of CDN how about hosting Images and CSS files on multiple hosts? i.e. img.uft.org and css.uft.org. That is something I took away from the consumersearch.org session from DrupalCon2011. THoughts? I am just not sure how to implement it. Not to mention I am in favor of doing all I can on the back-end first before making changes on the front-end.

What do you think?

Before doing a CDN (which is

gchaix's picture

Before doing a CDN (which is a good idea if it'll actually help), try a pseudo-CDN in your VCL along with something like the CDN module (http://drupal.org/project/cdn) that splits the requests over multiple domain names:

In your Varnish vcl_recv:

    if (req.http.host ~ "^cdn[1-3].") {
        set req.http.host = regsub(req.http.host, "^cdn[1-3]
.", "");
    }

Set CNAMEs for cdn1.yourdomain.org, cdn2.yourdomain.org, etc. to point to your Varnish instance and then spread your image loads, CSS, etc. over the domain names. Varnish will handle the requests without breaking a sweat and it'll let your visitors' browsers parallelize the requests across multiple domains. It's free and may well help you figure out if a CDN will help, and quite possible would help significantly on its own.

This won't actually work

dalin's picture

This won't actually work because for the browser to download assets in parallel the domains also need to be on a separate IP address. IIRC @mikeytown2 did some research proving this once.

--


Dave Hansen-Lange
Director of Technical Strategy, Advomatic.com
Pronouns: he/him/his

Ah! I stand corrected. I

gchaix's picture

Ah! I stand corrected. I thought I'd seen it work when I tested it, but I may have been mistaken.

@dalin is right on (as

gchaix's picture

@dalin is right on (as usual). As long as the backend is setting the SESS cookie, Varnish isn't helping much. It's still caching a lot of the static assets, but the actual page rendering is still being passed to the backend. That's probably why you feel Varnish is a "moving target."

Get rid of the session cookie and reduce the number of HTTP requests and you'll see a significant improvement in the rendering time.

@gchaix thanks We're kinda

dalin's picture

@gchaix thanks

We're kinda getting into the deeper weeds here, but if you have a session cookie, and all static resources are being served from the same domain as the HTML doc, then not even the static resources will be cached by Varnish since HTTP requests for these will include the session cookie.

--


Dave Hansen-Lange
Director of Technical Strategy, Advomatic.com
Pronouns: he/him/his

I'm pretty sure the

gchaix's picture

I'm pretty sure the locally-hosted static elements are still cached. Looking at the HTTP headers on his front page in Firebug I see Varnish hit headers being set on those requests.

Ah right, that's because the

dalin's picture

Ah right, that's because the VCL is setup to strip all cookies for static resources - In order to get Varnish serving static resources for authenticated users. It has the added benefit of keeping Varnish working for static resources even though a session cookie has started appearing.

--


Dave Hansen-Lange
Director of Technical Strategy, Advomatic.com
Pronouns: he/him/his

Where can I search for $_SESSION

repoman's picture

Where should I be searching to find the $_SESSION or session cookie you are talking about? Headers? I am also scouring through our code and there are many references to this, however, I am not sure what I should be looking for.

Session Table

mikeytown2's picture

Checkout the session table and see what value is getting set for anonymous users. Then look for the module that sets that session key value pair.

Autologout??

repoman's picture

@miketown2 - So does this mean that the culprit is our autologout module?

From Staging:


  uid: 0
  sid: d272sgsr1i5sihs99quc05jpg5

hostname: 10.52.208.222
timestamp: 1301945690
cache: 0
session: autologout_hits|a:1:{i:0;i:1301945689;}
*************************** 39. row ***************************
uid: 0
sid: dac9ddbe323489c5bc36a75344a6e96a
hostname: 172.16.0.110
timestamp: 1301938966
cache: 0
session: autologout_hits|a:1:{i:0;i:1301938965;}
*************************** 40. row ***************************
uid: 0
sid: e281136fe66c361aeae852a4f67c05db
hostname: 10.52.208.222
timestamp: 1301925717
cache: 0
session: autologout_hits|a:1:{i:0;i:1301925712;}
*************************** 41. row ***************************
uid: 0
sid: e7bdb4fa1cac7bbe18e26d23cb300fdd
hostname: 172.16.0.150
timestamp: 1302017654
cache: 0
session: autologout_hits|a:1:{i:0;i:1302017651;}

Yes this means that the

dalin's picture

Yes this means that the culprit is autologout.

--


Dave Hansen-Lange
Director of Technical Strategy, Advomatic.com
Pronouns: he/him/his

Session

rjbrown99's picture

Here's a thread in the masquerade module issue queue related to tracking down where sessions are created. (That module used to create sessions for anonymous users, it doesn't do that now thanks to that issue/patch.) Just thought it had some good points about sessions.

http://drupal.org/node/705858

If you are on a Linux/Unix OS you could always just find+grep your module tree for it.

cd /my/module/dir
find . -print -exec grep -H -n -i "_SESSION" {} \; | grep "_SESSION"

We have lots of modules that

repoman's picture

We Lots of modules that appear with the _SESSION

Take a look

./all/modules/contrib/hierarchical_select/hierarchical_select.module:375: if (!isset($_SESSION['hsid'])) {
./all/modules/contrib/hierarchical_select/hierarchical_select.module:376: $_SESSION['hsid'] = 0;
./all/modules/contrib/hierarchical_select/hierarchical_select.module:382: $_SESSION['hsid'] = ($_SESSION['hsid'] + 1) % 100;
./all/modules/contrib/hierarchical_select/hierarchical_select.module:384: $hsid = $_SESSION['hsid'];

./all/modules/contrib/subscriptions/subscriptions.install:342: if (!isset($_SESSION['subscriptions_update_7'])) {
./all/modules/contrib/subscriptions/subscriptions.install:343: $_SESSION['subscriptions_update_7'] = 0;
./all/modules/contrib/subscriptions/subscriptions.install:344: $_SESSION['subscriptions_update_7_max'] = db_result(db_query('SELECT MAX(uid) FROM {users}'));
./all/modules/contrib/subscriptions/subscriptions.install:351: $result = db_query_range("SELECT uid FROM {users} WHERE uid > %d ORDER BY uid ASC", $_SESSION['subscriptions_update_7'], 0, $limit);
./all/modules/contrib/subscriptions/subscriptions.install:370: $_SESSION['subscriptions_update_7'] = $usr->uid;
./all/modules/contrib/subscriptions/subscriptions.install:373: if ($_SESSION['subscriptions_update_7'] == $_SESSION['subscriptions_update_7_max']) {
./all/modules/contrib/subscriptions/subscriptions.install:376: unset($_SESSION['subscriptions_update_7']);
./all/modules/contrib/subscriptions/subscriptions.install:377: unset($_SESSION['subscriptions_update_7_max']);
./all/modules/contrib/subscriptions/subscriptions.install:380: return array('#finished' => $_SESSION['subscriptions_update_7'] / $_SESSION['subscriptions_update_7_max']);

./all/modules/contrib/image/image.module:312: if (!$_POST && !empty($_SESSION['image_upload'])) {
./all/modules/contrib/image/image.module:313: unset($_SESSION['image_upload']);
./all/modules/contrib/image/image.module:420: $_SESSION['image_upload'] = $form_state['values']['images'];
./all/modules/contrib/image/image.module:423: if (empty($_SESSION['image_upload'])) {
./all/modules/contrib/image/image.module:430: if (!empty($_SESSION['image_upload'])) {
./all/modules/contrib/image/image.module:431: $form_state['values']['images'] = $_SESSION['image_upload'];
./all/modules/contrib/image/image.module:433: unset($_SESSION['image_upload']);

./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs_taxonomy/custom_breadcrumbs_taxonomy.inc:156: $_SESSION['custom_breadcrumbs_previous_term'] = $tid;
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs_taxonomy/custom_breadcrumbs_taxonomy.inc:158: elseif (isset($_SESSION['custom_breadcrumbs_previous_term'])) {
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs_taxonomy/custom_breadcrumbs_taxonomy.inc:159: return $_SESSION['custom_breadcrumbs_previous_term'];
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs_taxonomy/.svn/text-base/custom_breadcrumbs_taxonomy.inc.svn-base:156: $_SESSION['custom_breadcrumbs_previous_term'] = $tid;
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs_taxonomy/.svn/text-base/custom_breadcrumbs_taxonomy.inc.svn-base:158: elseif (isset($_SESSION['custom_breadcrumbs_previous_term'])) {
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs_taxonomy/.svn/text-base/custom_breadcrumbs_taxonomy.inc.svn-base:159: return $_SESSION['custom_breadcrumbs_previous_term'];
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs.admin.inc:19: if (empty($_SESSION['custom_breadcrumbs_overview_filter'])) {
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs.admin.inc:27: foreach ($_SESSION['custom_breadcrumbs_overview_filter'] as $filter) {
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs.admin.inc:690: $session = &$_SESSION['custom_breadcrumbs_overview_filter'];
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs.admin.inc:764: $_SESSION['custom_breadcrumbs_overview_filter'][] = array($filter, $form_state['values'][$filter]);
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs.admin.inc:769: array_pop($_SESSION['custom_breadcrumbs_overview_filter']);
./all/modules/contrib/custom_breadcrumbs/custom_breadcrumbs.admin.inc:772: $_SESSION['custom_breadcrumbs_overview_filter'] = array();

./all/modules/contrib/filefield/filefield.module:167: if (empty($cck_files) && !($file->status == 0 && isset($_SESSION['filefield_access']) && in_array($file->fid, $_SESSION['filefield_access']))) {

./all/modules/contrib/filefield/filefield_widget.inc:380: $_SESSION['filefield_access'][] = $item['fid'];

./all/modules/contrib/memcache/memcache.inc:57: $cache_tables = isset($_SESSION['cache_flush']) ? $_SESSION['cache_flush'] : NULL;
./all/modules/contrib/memcache/memcache.inc:60: // Expire the $_SESSION['cache_flush'] variable array if it is older than
./all/modules/contrib/memcache/memcache.inc:64: unset($_SESSION['cache_flush']);
./all/modules/contrib/memcache/memcache.inc:202: if (is_array($_SESSION['cache_flush'])) {
./all/modules/contrib/memcache/memcache.inc:203: $cache_tables = $_SESSION['cache_flush'];
./all/modules/contrib/memcache/memcache.inc:209: $_SESSION['cache_flush'] = $cache_tables;

./all/modules/contrib/autologout/autologout.module:165: if ( !isset($_SESSION['autologout_hits']) ) {
./all/modules/contrib/autologout/autologout.module:166: $_SESSION['autologout_hits'] = array();
./all/modules/contrib/autologout/autologout.module:168: $_SESSION['autologout_hits'][] = time();
./all/modules/contrib/autologout/autologout.module:185: if (!isset($_SESSION['lastaccess'])) {
./all/modules/contrib/autologout/autologout.module:186: $_SESSION['lastaccess'] = $nowtime;
./all/modules/contrib/autologout/autologout.module:190: if ( isset($_SESSION['autologout_hits']) ) {
./all/modules/contrib/autologout/autologout.module:191: foreach($_SESSION['autologout_hits'] as $hit) {
./all/modules/contrib/autologout/autologout.module:192: if ( (int)$hit - (int)$_SESSION['lastaccess'] > 0 ) {
./all/modules/contrib/autologout/autologout.module:194: if ( ((int)$hit - (int)$_SESSION['lastaccess']) < $timeout ) {
./all/modules/contrib/autologout/autologout.module:196: $_SESSION['lastaccess'] = $hit;
./all/modules/contrib/autologout/autologout.module:203: if ( ($nowtime - (int)$_SESSION['lastaccess']) < $timeout ) {
./all/modules/contrib/autologout/autologout.module:206: $_SESSION['lastaccess'] = $nowtime;
./all/modules/contrib/autologout/autologout.module:207: $_SESSION['autologout_hits'] = array($nowtime);
./all/modules/contrib/autologout/autologout.module:218: unset($_SESSION['lastaccess']);
./all/modules/contrib/autologout/autologout.module:269: $_SESSION['lastaccess'] = time();
./all/modules/contrib/autologout/autologout.module:332: $_SESSION['lastaccess'] = time();

./all/modules/contrib/panels/includes/display-layout.inc:39: $change_form_state['layout'] = $_SESSION['layout'][$display->did] = $form_state['layout'];
./all/modules/contrib/panels/includes/display-layout.inc:44: $change_form_state['layout'] = $_SESSION['layout'][$display->did];
./all/modules/contrib/panels/includes/.svn/text-base/display-layout.inc.svn-base:39: $change_form_state['layout'] = $_SESSION['layout'][$display->did] = $form_state['layout'];
./all/modules/contrib/panels/includes/.svn/text-base/display-layout.inc.svn-base:44: $change_form_state['layout'] = $_SESSION['layout'][$display->did];

./all/modules/contrib/webform/translations/ja.po:312:msgid "You can also use %server[key] to add any of the special PHP $_SERVER variables, %session[key] to add any of the special PHP $_SESSION variables and %get[key] to create prefilled forms from the URL. %cookie, %request and %post also work with their respective PHP variables. For example %server[HTTP_USER_AGENT], %session[id], or %get[q]."
./all/modules/contrib/webform/translations/ja.po:313:msgstr "PHPの$_SERVER変数の値を追加するのに %server[key] を、$_SESSION変数の値を追加するのに %session[key] を、URLから入力済みのフォームを作成するのに %get[key] を利用することができます。%cookie や %request、%post もまた、それぞれ対応するPHP変数の値となります。例) %server[HTTP_USER_AGENT]、%session[id]、%get[q]。"
./all/modules/contrib/webform/translations/fi.po:883:msgid "You can use %server[key] to add any of the special PHP $_SERVER variables, %session[key] to add any of the special PHP $_SESSION variables and %get[key] to create prefilled forms from the URL. %cookie, %request and %post also work with their respective PHP variables. For example %server[HTTP_USER_AGENT], %session[id], or %get[q]."
./all/modules/contrib/webform/translations/hu.po:909:"php.net/reserved.variables#reserved.variables.session\">$_SESSION "
./all/modules/contrib/webform/translations/cs.po:883:msgid "You can use %server[key] to add any of the special PHP $_SERVER variables, %session[key] to add any of the special PHP $_SESSION variables and %get[key] to create prefilled forms from the URL. %cookie, %request and %post also work with their respective PHP variables. For example %server[HTTP_USER_AGENT], %session[id], or %get[q]."
./all/modules/contrib/webform/translations/cs.po:884:msgstr "Symbol %server[key] můžete použít k přidání libovolné speciální proměnné PHP $_SERVER. Symbol %session[key] slouží k přidání libovolné speciální proměnné PHP $_SESSION, symbol %get[key] pak k vytvoření předvyplněných polí formuláře z URL. Symboly %cookie, %request a %post lze rovněž používat s odpovídajícími proměnnými PHP. Například %server[HTTP_USER_AGENT], %session[id] nebo %get[q]."
./all/modules/contrib/webform/translations/sk.po:1113:"href=\"http://www.php.net/reserved.variables#reserved.variables.session\">$_SESSION "
./all/modules/contrib/webform/translations/sk.po:1124:"href=\"http://www.php.net/reserved.variables#reserved.variables.session\">$_SESSION "

./all/modules/contrib/jquery_ui/jquery.ui/demos/functional/js/chili-recipes.js:137: , global : { exp: /(?:\$GLOBALS|\$_COOKIE|\$_ENV|\$_FILES|\$_GET|\$_POST|\$_REQUEST|\$_SERVER|\$_SESSION|\$php_errormsg)\b/ }
./all/modules/contrib/jquery_ui/jquery.ui/demos/functional/js/.svn/text-base/chili-recipes.js.svn-base:137: , global : { exp: /(?:\$GLOBALS|\$_COOKIE|\$_ENV|\$_FILES|\$_GET|\$_POST|\$_REQUEST|\$_SERVER|\$_SESSION|\$php_errormsg)\b/ }

./all/modules/contrib/date/date_tools/date_tools.module:1129: //$_SESSION['messages'] = $messages;

./all/modules/contrib/captcha/captcha.module:513: $_SESSION['captcha_success_form_ids'][$form_id] = $form_id;

./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:170: if ($_GET['q'] != 'views-bulk-operations/js/pager' && isset($_SESSION['vbo_values']) && !isset($_SESSION['vbo_values'][$_GET['q']])) {
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:171: unset($_SESSION['vbo_values']);
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:204: if (isset($_SESSION['vbo_values'][$_GET['q']])) {
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:205: $objects = $_SESSION['vbo_values'][$_GET['q']]['objects'];
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:214: $default_operation = $_SESSION['vbo_values'][$_GET['q']]['operation'];
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:399: $_SESSION['vbo_values'][$_GET['q']] = $form_state['values'];
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:413: $_SESSION['vbo_values'][$_GET['q']] = $form_state['values'];
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:465: $_SESSION['vbo_values'][$_GET['q']]['objects'] = array('selection' => $selection, 'select_all' => $select_all);
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:528: unset($_SESSION['vbo_values'][$_GET['q']]);
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:594: $_SESSION['vbo_options']['display_result'] = $options['display_result'];
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:595: $_SESSION['vbo_options']['operation'] = $operation;
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:596: $_SESSION['vbo_options']['params'] = $params;
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:597: $_SESSION['vbo_options']['object_info'] = $object_info;
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:683: $operation = $_SESSION['vbo_options']['operation'];
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:684: $params = $_SESSION['vbo_options']['params'];
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:685: $object_info = $_SESSION['vbo_options']['object_info'];
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:749: if ($display_result || @$_SESSION['vbo_options']['display_result']) {
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:752: unset($_SESSION['vbo_options']); // unset the options which were used for just one invocation
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:1244: $_SESSION['vbo_values'][$url]['objects']['select_all'] = $select_all;
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:1246: $_SESSION['vbo_values'][$url]['objects']['pages'][$page] = array_fill_keys(explode(',', $selection), TRUE);
./all/modules/contrib/views_bulk_operations/views_bulk_operations.module:1260: unset($_SESSION['messages']['error'][array_search($message, $_SESSION['messages']['error'])]);

./all/modules/contrib/devel/devel.module:26: return '

'. t('Here are the contents of your $_SESSION variable.') .'

';
./all/modules/contrib/devel/devel.module:131: 'description' => 'List the contents of $_SESSION.',
./all/modules/contrib/devel/devel.module:1279: $output = kprint_r($_SESSION, TRUE);

./all/modules/contrib/devel/krumo/class.krumo.php:480: * Prints a list of all the values from the $_SESSION array.
./all/modules/contrib/devel/krumo/class.krumo.php:497:This is a list of all the values from the <b>$_SESSION</b> array.
./all/modules/contrib/devel/krumo/class.krumo.php:500: return krumo::dump($_SESSION);

./all/modules/contrib/devel/krumo/docs/Krumo/.svn/text-base/krumo.html.svn-base:871:

Prints a list of all the values from the $_SESSION array.

./all/modules/contrib/devel/krumo/docs/Krumo/krumo.html:871:

Prints a list of all the values from the $_SESSION array.

./all/modules/contrib/devel/krumo/docs/elementindex.html:357:

Prints a list of all the values from the $_SESSION array.

./all/modules/contrib/devel/krumo/docs/elementindex_Krumo.html:354:

Prints a list of all the values from the $_SESSION array.

./all/modules/contrib/views/handlers/views_handler_filter.inc:552: if (!$status && isset($_SESSION['views'][$this->view->name][$display_id])) {
./all/modules/contrib/views/handlers/views_handler_filter.inc:553: $session = &$_SESSION['views'][$this->view->name][$display_id];
./all/modules/contrib/views/handlers/views_handler_filter.inc:564: if (!isset($_SESSION['views'][$this->view->name][$display_id])) {
./all/modules/contrib/views/handlers/views_handler_filter.inc:565: $_SESSION['views'][$this->view->name][$display_id] = array();
./all/modules/contrib/views/handlers/views_handler_filter.inc:568: $session = &$_SESSION['views'][$this->view->name][$display_id];

./all/modules/contrib/views/includes/form.inc:18: if (isset($_SESSION['batch_form_state'])) {
./all/modules/contrib/views/includes/form.inc:22: $form_state = $_SESSION['batch_form_state'];
./all/modules/contrib/views/includes/form.inc:23: unset($_SESSION['batch_form_state']);

./all/modules/contrib/views/includes/admin.inc:59: unset($_SESSION['views']['#admin']);
./all/modules/contrib/views/includes/admin.inc:63: if (isset($_SESSION['views']['#admin']) && is_array($_SESSION['views']['#admin'])) {
./all/modules/contrib/views/includes/admin.inc:64: $_GET += $_SESSION['views']['#admin'];
./all/modules/contrib/views/includes/admin.inc:68: $_SESSION['views']['#admin'] = $_GET;
./all/modules/contrib/views/includes/admin.inc:69: unset($_SESSION['views']['#admin']['q']);
./all/modules/contrib/views/includes/admin.inc:317: if (!empty($_SESSION['views']['#admin'])) {
./all/modules/contrib/views/includes/view.inc:173: if (empty($this->exposed_input) && !empty($_SESSION['views'][$this->name][$display_id])) {
./all/modules/contrib/views/includes/view.inc:174: $this->exposed_input = $_SESSION['views'][$this->name][$display_id];

./all/modules/contrib/rules/rules_forms/rules_forms.admin.inc:18: '#default_value' => isset($_SESSION['rules_forms_message']) ? $_SESSION['rules_forms_message'] : FALSE,
./all/modules/contrib/rules/rules_forms/rules_forms.admin.inc:24: '#default_value' => isset($_SESSION['rules_forms_element_ids']) ? $_SESSION['rules_forms_element_ids'] : FALSE,
./all/modules/contrib/rules/rules_forms/rules_forms.admin.inc:56: $_SESSION['rules_forms_message'] = (bool) $form_values['values']['enable_form_activation_message'];
./all/modules/contrib/rules/rules_forms/rules_forms.admin.inc:57: $_SESSION['rules_forms_element_ids'] = (bool) $form_values['values']['enable_form_element_ids'];

./all/modules/contrib/rules/rules_forms/rules_forms.module:58: if (!empty($_SESSION['rules_forms_element_ids'])) {
./all/modules/contrib/rules/rules_forms/rules_forms.module:63: if (!empty($_SESSION['rules_forms_message'])) {

./all/modules/contrib/securepages/securepages.module:40: if (!isset($_SESSION['securepages_redirect'])) {
./all/modules/contrib/securepages/securepages.module:57: if (!isset($_SESSION['securepages_redirect'])) {
./all/modules/contrib/securepages/securepages.module:61: unset($_SESSION['securepages_redirect']);
./all/modules/contrib/securepages/securepages.module:176: $_SESSION['securepages_redirect'] = TRUE;

./all/modules/contrib/ctools/includes/form.inc:31: if (isset($_SESSION['batch_form_state'])) {
./all/modules/contrib/ctools/includes/form.inc:35: $form_state = $_SESSION['batch_form_state'];
./all/modules/contrib/ctools/includes/form.inc:36: unset($_SESSION['batch_form_state']);

./all/modules/contrib/ctools/includes/object-cache.inc:61: if (empty($GLOBALS['user']->uid) && empty($_SESSION['ctools_session_id'])) {
./all/modules/contrib/ctools/includes/object-cache.inc:62: $_SESSION['ctools_hold_session'] = TRUE;

./all/modules/contrib/ctools/plugins/export_ui/ctools_export_ui.class.php:162: unset($_SESSION['ctools_export_ui'][$this->plugin['name']]);
./all/modules/contrib/ctools/plugins/export_ui/ctools_export_ui.class.php:179: if (isset($_SESSION['ctools_export_ui'][$this->plugin['name']]) && is_array($_SESSION['ctools_export_ui'][$this->plugin['name']])) {
./all/modules/contrib/ctools/plugins/export_ui/ctools_export_ui.class.php:180: $input = $_SESSION['ctools_export_ui'][$this->plugin['name']];
./all/modules/contrib/ctools/plugins/export_ui/ctools_export_ui.class.php:184: $_SESSION['ctools_export_ui'][$this->plugin['name']] = $input;
./all/modules/contrib/ctools/plugins/export_ui/ctools_export_ui.class.php:185: unset($_SESSION['ctools_export_ui'][$this->plugin['name']]['q']);

./all/modules/contrib/ctools/page_manager/page_manager.admin.inc:53: unset($_SESSION['page_manager']['#admin']);
./all/modules/contrib/ctools/page_manager/page_manager.admin.inc:67: if (isset($_SESSION['page_manager']['#admin']) && is_array($_SESSION['page_manager']['#admin'])) {
./all/modules/contrib/ctools/page_manager/page_manager.admin.inc:68: $input = $_SESSION['page_manager']['#admin'];
./all/modules/contrib/ctools/page_manager/page_manager.admin.inc:72: $_SESSION['page_manager']['#admin'] = $input;
./all/modules/contrib/ctools/page_manager/page_manager.admin.inc:73: unset($_SESSION['page_manager']['#admin']['q']);

./all/modules/custom/uft_file/uft_file.module:58: array_pop($_SESSION['messages']['error']);
./all/modules/custom/uft_file/uft_file.module:63: array_pop($_SESSION['messages']['error']);

./all/modules/custom/uft_user/uft_user.pages.inc:14: if (!$_SESSION['uft_user_email_option']) {drupal_access_denied();exit;}
./all/modules/custom/uft_user/uft_user.pages.inc:15: unset($_SESSION['messages']);// We don't want "Registration successful. You are now logged in."
./all/modules/custom/uft_user/uft_user.pages.inc:23: '#options' => array($account->mail => $account->mail, $_SESSION['uft_user_email_option'] => $_SESSION['uft_user_email_option']),
./all/modules/custom/uft_user/uft_user.pages.inc:67: $_SESSION['update_plunkit'] = 0;
./all/modules/custom/uft_user/uft_user.pages.inc:81: $_SESSION['update_plunkit'] = 1;
./all/modules/custom/uft_user/uft_user.pages.inc:89: $_SESSION['uft_user_message'][] = t('Your e-mail address has been updated. To validate your e-mail address change, you must go to your e-mail account and click on the validation link. You will not be able to log in until you take this step.');
./all/modules/custom/uft_user/uft_user.pages.inc:187: unset($_SESSION['messages']);// We don't need any messages here really.
./all/modules/custom/uft_user/uft_user.pages.inc:256: unset($_SESSION['messages']);
./all/modules/custom/uft_user/uft_user.pages.inc:428: $_SESSION['update_plunkit'] = 0;

./all/modules/custom/uft_user/uft_user.module:137: if ($account->uft_user['update_plunkit'] == 1 || $_SESSION['update_plunkit'] == 1) {
./all/modules/custom/uft_user/uft_user.module:143: if ($_SESSION['update_plunkit'] == 1) {
./all/modules/custom/uft_user/uft_user.module:165: $_SESSION['update_plunkit'] = 0;
./all/modules/custom/uft_user/uft_user.module:246: array_pop($_SESSION['messages']['error']);// Don't display the error.
./all/modules/custom/uft_user/uft_user.module:252: array_pop($_SESSION['messages']['error']);// Don't display the error.
./all/modules/custom/uft_user/uft_user.module:257: array_pop($_SESSION['messages']['error']);// Don't display the error.
./all/modules/custom/uft_user/uft_user.module:272: array_pop($_SESSION['messages']['error']);// Don't display the error.
./all/modules/custom/uft_user/uft_user.module:285: array_pop($_SESSION['messages']['error']);// Don't display the error.
./all/modules/custom/uft_user/uft_user.module:364: if (!empty($_SESSION['messages']['error'])) {
./all/modules/custom/uft_user/uft_user.module:366: foreach ($_SESSION['messages']['error'] as $key => $message) {
./all/modules/custom/uft_user/uft_user.module:368: unset($_SESSION['messages']['error'][$key]);
./all/modules/custom/uft_user/uft_user.module:377: unset($_SESSION['messages']['error'][$key]);
./all/modules/custom/uft_user/uft_user.module:393: $tmp_errors[] = $_SESSION['messages']['error'][$key];
./all/modules/custom/uft_user/uft_user.module:397: $_SESSION['messages']['error'] = $tmp_errors;
./all/modules/custom/uft_user/uft_user.module:576: if (is_array($_SESSION['uft_user_message']) && !empty($_SESSION['uft_user_message'])) {
./all/modules/custom/uft_user/uft_user.module:577: foreach ($_SESSION['uft_user_message'] as $key => $message) {
./all/modules/custom/uft_user/uft_user.module:579: unset($_SESSION['uft_user_message'][$key]);
./all/modules/custom/uft_user/uft_user.module:991: $_SESSION['update_plunkit'] = 1;
./all/modules/custom/uft_user/uft_user.module:993: $_SESSION['uft_user_email_option'] = $validate_info->previous_email;
./all/modules/custom/uft_user/uft_user.module:1003: $_SESSION['uft_user_email_option'] = $form_state['values']['mail'];
./all/modules/custom/uft_user/uft_user.module:1080: if (!empty($_SESSION['messages']['error'])) {
./all/modules/custom/uft_user/uft_user.module:1083: foreach ($_SESSION['messages']['error'] as $key => $message) {
./all/modules/custom/uft_user/uft_user.module:1085: unset($_SESSION['messages']['error'][$key]);
./all/modules/custom/uft_user/uft_user.module:1089: unset($_SESSION['messages']['error'][$key]);
./all/modules/custom/uft_user/uft_user.module:1100: $tmp_errors[] = $_SESSION['messages']['error'][$key];
./all/modules/custom/uft_user/uft_user.module:1104: $_SESSION['messages']['error'] = $tmp_errors;

./all/modules/custom/uft_workflow/uft_workflow.module:849: foreach ($_SESSION['messages']['status'] as $key => $tmp_message) {
./all/modules/custom/uft_workflow/uft_workflow.module:851: unset($_SESSION['messages']['status'][$key]);
./all/modules/custom/uft_workflow/uft_workflow.module:855: if (empty($_SESSION['messages']['status'])) unset($_SESSION['messages']['status']);
./all/modules/custom/uft_workflow/uft_workflow.module:1135: if (!empty($_SESSION['messages']['error']) && ($key = array_search(t('This content has been modified by another user, changes cannot be saved.'), $_SESSION['messages']['error'])) !== FALSE) {
./all/modules/custom/uft_workflow/uft_workflow.module:1136: unset($_SESSION['messages']['error'][$key]);
./all/modules/custom/uft_workflow/uft_workflow.module:1137: $_SESSION['messages']['error'] = array_values($_SESSION['messages']['error']);

./all/modules/custom/uft_petition/uft_petition.module:1728: if ($_SESSION['uft_petition_signing_thankyou_message']) {
./all/modules/custom/uft_petition/uft_petition.module:1731: '#value' => $_SESSION['uft_petition_signing_thankyou_message']
./all/modules/custom/uft_petition/uft_petition.module:1733: unset($_SESSION['uft_petition_signing_thankyou_message']);
./all/modules/custom/uft_petition/uft_petition.module:5279: $_SESSION['uft_petition_signing_thankyou_message'] = $message;

Find the cookie

Memcache - Only Misses

repoman's picture

First off I'd like to say thanks to all that have posted their thoughts. I am still looking into the session thing but I am having a hard time wrapping my head around the fact 'Hit' for Varnish is appearing in the header but several of you are saying that the Session is stopping that. I am using HTTPFox to look at the headers. Perhaps you could tell me what you are using.

In the meantime I am still pushing forward to optimizing the webhead. I noticed that Memcache was actually not working so I spent a few hours trying to get it to work and while I can see memcache process running and I see the bins I am still getting MISSes in brutis.

/etc/init.d/memcached

** From lullabot and modified it.

# Default cache.
memcached -m 32 -l 0.0.0.0 -p 11211 -d -u nobody
# Filter cache.
memcached -m 32 -l 0.0.0.0 -p 11212 -d -u nobody
# Menu cache.
memcached -m 32 -l 0.0.0.0 -p 11213 -d -u nobody
# Page cache. Bigger than most other caches.
memcached -m 128 -l 0.0.0.0 -p 11214 -d -u nobody
# Form cache.
memcached -m 32 -l 0.0.0.0 -p 11215 -d -u nobody
# Block cache.
memcached -m 32 -l 0.0.0.0 -p 11216 -d -u nobody
# Views data cache (may need to be increased if heavily used).
memcached -m 32 -l 0.0.0.0 -p 11217 -d -u nobody
# Sessions cache. 
memcached -m 16 -l 0.0.0.0 -p 11218 -d -u nobody
# Content cache. Holds fully loaded content type structures.
memcached -m 16 -l 0.0.0.0 -p 11219 -d -u nobody

Settings.php

// Setup the memcache admin module
require_once ('./sites/all/modules/contrib/memcache/dmemcache.inc');
//$conf['cache_inc'] ='sites/all/modules/contrib/memcache/memcache.inc';
$conf = array(
'cache_inc' => './sites/all/modules/contrib/memcache/memcache.inc',
'session_inc' => './sites/all/modules/contrib/memcache/memcache-session.inc',
'memcache_servers' => array(
'192.168.52.111:11211' => 'default',
'192.168.52.111:11212' => 'filter',
'192.168.52.111:11213' => 'menu',
'192.168.52.111:11214' => 'page',
'192.168.52.111:11215' => 'form',
'192.168.52.111:11216' => 'block',
'192.168.52.111:11217' => 'views',
'192.168.52.111:11218' => 'other',
'192.168.52.111:11219' => 'content',
),
'memcache_bins' => array(
'cache' => 'default',
'cache_filter' => 'filter',
'cache_menu' => 'menu',
'cache_page' => 'page',
'cache_form' => 'form',
'cache_block' => 'block',
'cache_views_data' => 'views',
'session' => 'other',
'users' => 'other',
'cache_content' => 'content',
),
);

Ouput from Brutis

Brutis 5 Connections

Type Ops/sec Hits/sec Misses/sec Fails/sec Latency MB/sec

Sets: 491.45 --- --- 0.00 0.000188 0.12
Gets: 4,913.03 219.98 4,693.05 0.00 0.000155 0.05

Totals: 5,404.48 219.98 4,693.05 0.00 0.000172 0.17

SETS GETS

Host Ops/sec Latency MB/sec Ops/sec Latency MB/sec

svapp02 491.45 0.000188 0.12 4,913.03 0.000155 0.05

Autologout has been disabled

repoman's picture

While I try to figure out a way to strip it from Varnish.

Now I'm trying to validate and vet the memcache config. I searched other posts and I'm just not seeing the necessary information needed to make sure this is working properly. Brutis showing a lot more misses than hits.

While I am parsing through the documentation here: http://drupal.org/node/326504

It is not very clear based on our current set up, hence the leaning on the experts here:

All VMs
Our first server hit is the Proxy/Pound Varnish server. We are looking to introduce RedHat Clustering and add another Varnish proxy in the near future.
The next server is the pressflow web head. We are looking to scale this up to 3 web heads in the future, all accessing an NFS mount for shared resources such as 'Files'
The Web head talks to our MySQL Master/Slave servers

That is it in a nutshell. I see lots of talk about Varnish, Memcache, CacheRouter, APC, Boost and before I start trying all of these; which for some reason I am having a hard time with memcache. I'd like to know from your experience and based on my setup, what you feel is a good direction to head towards and what ways can I get a good baseline.

I know that @gchaix & @dailin both said we need to get our HTTP requests down. I had a meeting with our front end people about that and it's a work in progress. One thought was to off-load some of these images to another host (poor man's CDN) as all our traffic is primarily local. WebPagetest.org showed that on the initial test the 'first time to byte' can take an average of 2 sec. So I am looking into that as well.

So as you can see there is a lot to look at and learning on the fly as we only took on this site in September. I'm loving Drupal and all it has to offer it's just a bit of a beast of information and I need a starting good point.

Thanks gchaix, dailin, rjbrown99 & miketown2 for your continued help!

Not to repeat...

rjbrown99's picture

Not to repeat what I suggested earlier, but I'm going to repeat it :) I think you should really consider giving NewRelic a try. The reason for that is because I don't think you can be sure exactly where you are seeing performance issues so you may be trying to fix the wrong thing. What I really like about NewRelic is that it can map out response time at each tier in the same graph - i.e. how much time is spent in PHP, how much time is spent in Memcache, and how much time is spent in the DB. You can visually see exactly which part of the app is performing poorly, down to the actual PHP function calls or database queries that are taking the longest amount of time.

I'll give you an example of why this helped me. I was in a similar place, trying to tune/fix the database and memcache and wondering why performance was not great. When I started to look at the NewRelic graphs, they showed that the vast majority of my response time was being spent at the PHP level. This was a curious discovery, and it sent me down the path of looking at my Drupal module and theme code rather than Memcache+DB. I noticed that there were a number of places where I was doing a node_load for things like CCK text fields just to put together the user's full name (i.e. cck text field for firstname, cck text field for lastname.) I simply wrapped that in a cache_set/cache_get block of code and boom you see an instant boost in PHP response time. No more loading of nodes, just loading of cached values from a cache table in memcache.

I had a similar issue with the flag module. NewRelic was showing a huge number of hits to the flag tables in the database, which should not have been the case. The reason for it is because I had a checkbox in the flag module turned on: "display link on node page". Well, only authenticated users on my site can flag stuff but the huge number of hits clued me in that flag was being rendered and queried for unauthenticated users. The net result of having that checkbox on is that for unauthenticated users, the flag code was running all the way up to the point where it hit the flag access part to not show it. I.E. the queries and flag code was being executed when it really didn't need to be because they weren't going to be displayed anyway. My theme-layer fix was easy -

<?php if($logged_in): ?>
  <?php print flag_create_link('myflag", $node->nid); ?>
<?php endif; ?>

Now the flag code is only even attempted for users who are logged in, and all of those database queries and php code executions dropped off and performance increased.

I wouldn't have known either of those things by running network benchmark tests or watching varnishtop or memcache cache statistic pages. I would have likely continued down the path of trying to fix memcache and database performance settings when it wasn't really the problem to start with.

I hope that helps, and my NewRelic commercial is now over :)

New Relic

repoman's picture

Hey rjbrown99 thanks! I do have new relic turned on in our staging environment but there just aren't enough hits there to really see anything, then again I am new to this so I am still unsure what I should be looking for as I don't know what is acceptable behavior. I enabled this in both environments so I can what the differences are.

Perhaps you can tell me if the following is normal and then I can start hitting the priorities.

Production:

Start Time URL Resp. Time URL Avg.
14:01:02 /cron.php 21,640 ms 11,218 ms
14:06:13 /www/delivery/lg.php 11,457 ms 183 ms
14:16:16 /drupal_get_form 8,480 ms 1,000 ms
14:02:19 /page_manager_node_view 5,206 ms 1,308 ms
14:04:21 /views_page 3,747 ms 1,514 ms
14:08:20 /page_manager_node_view 3,717 ms 1,308 ms
14:21:21 /views_page 3,692 ms 1,514 ms
14:05:20 /page_manager_node_view 3,658 ms 1,308 ms
14:29:21 /views_page 3,505 ms 1,514 ms
14:09:21 /page_manager_page_execute 3,385 ms 1,220 ms
14:00:21 /apachesolr_search_view 3,126 ms 1,189 ms
14:11:22 /page_manager_node_view 3,074 ms 1,308 ms
14:10:21 /page_manager_node_view 2,924 ms 1,308 ms
14:19:22 /page_manager_node_view 2,905 ms 1,308 ms
14:07:22 /page_manager_node_view 2,883 ms 1,308 ms
14:23:22 /page_manager_page_execute 2,874 ms 1,220 ms
14:25:22 /page_manager_node_view 2,789 ms 1,308 ms
14:13:22 /page_manager_node_view 2,765 ms 1,308 ms
14:17:21 /page_manager_page_execute 2,741 ms 1,220 ms
14:26:21 /page_manager_node_view 2,737 ms 1,308 ms
14:14:22 /views_page 2,722 ms 1,514 ms

This seems to be coming from ctools/page_manager/plugins/node_view.inc

Normal

rjbrown99's picture

Well I wouldn't say anything looks "normal" as what you see will be a factor of what modules you are using, how the site is implemented, and your traffic mix. But what you are looking at in that list are a series of Drupal function calls as well as a few php scripts.

You can see cron.php taking 21640ms, so you might consider looking at Elysia Cron which allows for granular scheduling of each cron hook and tracking of how long each one is taking.

I'd also look at whatever lg.php is, which sounds like some kind of custom php script or monitoring tool. In some cases monitoring tools drag your performance down as much as anything else. I had to kill cacti scripts for that very reason.

The rest of it is hard to interpret without looking at full traces. With NewRelic Gold you should be able to follow the PHP->SQL functions and queries to determine if you think the code is doing what it should be.

New Relic & Time to first byte

repoman's picture

Thanks for the input. We have another 20 days on the Gold eval and I really think that this is awesome. the lg.php script is run via our openx maintenance cron that runs hourly.

Webpagetest.org is pointing the delay at 'Time to first byte' and I am trying to track down what might be the delay here. Any experience with troubleshooting 'T2FB'?

Network

rjbrown99's picture

As was mentioned above, first make sure there is no session cookie. Anonymous user caching and static caching in general isn't going to work until you fix that issue (if you haven't already.)

I'm a network geek at heart, so what I would probably do is to see which part of your stack is creating the bottleneck, I might suggest taking a few simultaneous sniffer traces and see where you are doing the waiting. IE -

Client -> Proxy
Proxy -> Web head
Web head -> Database

Try to determine where you are hanging up, specifically which layer is slowing you down and creating a situation where you are waiting. I can't even speculate which layer it could be as it might be anything from lack of proxy caching, fragmented APC, network speeds/feeds, slow database queries, etc etc.

High performance

Group notifications

This group offers an RSS feed. Or subscribe to these personalized, sitewide feeds: