Memcached set is too slow

1,467 views
Skip to first unread message

Chaosty

unread,
Feb 23, 2010, 8:31:25 PM2/23/10
to memcached
We have found that Memcahed::set stores items around 100-200kbs for
0.10-0.11 seconds, its too slow. Compression is turned off. Any
suggestions?

PHP5.3, libmemcached 0.35, memcached 1.0.0

Eric Lambert

unread,
Feb 23, 2010, 8:42:47 PM2/23/10
to memc...@googlegroups.com
>
> PHP5.3, libmemcached 0.35, memcached 1.0.0

Is this really the version of the memcached server you are using (1.0.0)
If so, that is certainly out-of-date. Latest version is 1.4.*.

Eric

me from

unread,
Feb 23, 2010, 9:09:36 PM2/23/10
to memc...@googlegroups.com
No. Sorry for misunderstanding, its my bad. Its php extension (PECL) of version 1.0.0.

Memcached is 1.4.4

Juri Bracchi

unread,
Feb 24, 2010, 4:02:08 AM2/24/10
to memc...@googlegroups.com
the latest memcache php extension version is 2.2.5

http://pecl.php.net/package/memcache

me from

unread,
Feb 24, 2010, 7:35:43 AM2/24/10
to memc...@googlegroups.com
We use memcached php extension, (http://pecl.php.net/package/memcached)

Adam Lee

unread,
Feb 24, 2010, 12:41:03 PM2/24/10
to memc...@googlegroups.com
What kind of hardware and software configurations are you using on the client and server sides?  

We have servers doing like 5M/s in and 10M/s out without even breaking a sweat...
--
awl

Marc Bollinger

unread,
Feb 24, 2010, 12:47:52 PM2/24/10
to memc...@googlegroups.com
And are you using persistent connections? There have been a handful of
threads recently, discussing setting up persistent connections with
PECL::memcached.

- Marc

me from

unread,
Feb 24, 2010, 1:22:44 PM2/24/10
to memc...@googlegroups.com
Adam we are on freebsd 7.2, as i said early we use PECL memcached 1.0.0 with libmemcached 0.35, the memcached version is 1.4.4.

We use our framework this is an init method

    public static function instance() {
        if (self::$instance === NULL) {
            // Create a new instance
            self::$instance = new Memcached ();
            self::$instance->setOption (Memcached::OPT_DISTRIBUTION, Memcached::DISTRIBUTION_CONSISTENT);
            self::$instance->addServers (array (array ('127.0.0.1', 11211, 100)));
        }
    }

and this is a set method that works fine with small data and stops with data > 100kbs

    public static function set($key, $item, $exp = 60) {
        return self::$instance->set ($key, $item, $exp);
    }

Marc, no we don't use persistent you can see it in our init method.

dormando

unread,
Feb 27, 2010, 7:41:10 PM2/27/10
to memc...@googlegroups.com
How are you performing the test? Is memcached over localhost or over the
network?

If you can reproduce this in isolation I'd be curious to see what
memcached and/or php are waiting on that takes so long (via strace or
similar).

Chaosty

unread,
Mar 1, 2010, 10:13:22 AM3/1/10
to memcached
The tests were performed by modifying the set method like this:

public static function set($key, $item, $exp = 60) {

$benchmark = Profiler::start ('Memory', 'Set: '. $key);
$return = self::$instance->set ($key, $item, $exp);
Profiler::stop ($benchmark);
return $return;
}

Then I figured out that almost each set is cost to us ~0.000079
seconds
but the big key costs ~0.099359 seconds

this is trace info with: truss -faedD -o /phplog
...
76982: 2.431621337 0.000014247 gettimeofday({1267456195.261569 },0x0)
= 0 (0x0)
76982: 2.431709896 0.000014806 gettimeofday({1267456195.261658 },0x0)
= 0 (0x0)
76982: 2.431964677 0.000045257 write(9,"set
b5e03d478da6b7b8e61095fec4eb"...,8196) = 8196 (0x2004)
76982: 2.432037871 0.000017600 write(9,"pr.parent_id = p.parent_id
(1)";"...,1360) = 1360 (0x550)
76982: 2.432097655 0.000015644 read(9,0x2aedb054,8196) ERR#35
'Resource temporarily unavailable'
76982: 2.532011750 0.099864927 poll({9/POLLIN},1,-1) = 1 (0x1)
76982: 2.532070696 0.000016482 read(9,"STORED\r\n",8196) = 8 (0x8)
76982: 2.532135509 0.000014248 gettimeofday({1267456195.362084 },0x0)
= 0 (0x0)
...
seems here's the problem: 76982: 2.532011750 0.099864927 poll({9/
POLLIN},1,-1) = 1 (0x1)

On Feb 28, 3:41 am, dormando <dorma...@rydia.net> wrote:
> How are you performing the test? Is memcached over localhost or over the
> network?
>
> If you can reproduce this in isolation I'd be curious to see what
> memcached and/or php are waiting on that takes so long (via strace or
> similar).
>
> On Wed, 24 Feb 2010, me from wrote:
> > Adam we are on freebsd 7.2, as i said early we use PECL memcached 1.0.0 with libmemcached 0.35, the memcached version is 1.4.4.
>
> > We use our framework this is an init method
>

> > ��� public static function instance() {
> > ��� ��� if (self::$instance === NULL) {
> > ��� ��� ��� // Create a new instance
> > ��� ��� ��� self::$instance = new Memcached ();
> > ��� ��� ��� self::$instance->setOption (Memcached::OPT_DISTRIBUTION, Memcached::DISTRIBUTION_CONSISTENT);
> > ��� ��� ��� self::$instance->addServers (array (array ('127.0.0.1', 11211, 100)));
> > ��� ��� }
> > ��� }


>
> > and this is a set method that works fine with small data and stops with data > 100kbs
>

> > ��� public static function set($key, $item, $exp = 60) {
> > ��� ��� return self::$instance->set ($key, $item, $exp);
> > ��� }


>
> > Marc, no we don't use persistent you can see it in our init method.
>

> > On Wed, Feb 24, 2010 at 8:47 PM, Marc Bollinger <mbollin...@gmail.com> wrote:
> >       And are you using persistent connections? There have been a handful of
> >       threads recently, discussing setting up persistent connections with
> >       PECL::memcached.
>
> >       - Marc
>

> > On Wed, Feb 24, 2010 at 9:41 AM, Adam Lee <a...@fotolog.biz> wrote:
> > > What kind of hardware and software configurations are you using on the
> > > client and server sides?
> > > We have servers doing like 5M/s in and 10M/s out without even breaking a
> > > sweat...
>

Chaosty

unread,
Mar 1, 2010, 10:24:31 AM3/1/10
to memcached
And here is strace
...
0.000085 [28b4f1ab] gettimeofday({1667458660, 1681273911}, NULL)
= 0 <0.000013>
0.000202 [28b5f2a3] write(9, "set
b5e03d478da6b7b8e61095fec4eb0"..., 8196) = 8196 <0.000038>
0.000091 [28b5f2a3] write(9, "pr.parent_id = p.parent_id
(1)\";s"..., 1360) = 1360 <0.000023>
0.000078 [28b5f2c3] read(9, 0x2aef6054, 8196) = -1 EAGAIN
(Resource temporarily unavailable) <0.000014>
0.000061 [28b09d6f] poll([{fd=574240058, events=POLLIN|POLLPRI|
POLLRDNORM|POLLWRBAND|POLLERR|POLLNVAL|0x6000}], 1, INFTIM) = 1
([{fd=1933255265, revent$
0.099064 [28b5f2c3] read(9, "STORED\r\n"..., 8196) = 8 <0.000018>
0.000090 [28b4f1ab] gettimeofday({875772260, 912536929}, NULL) =
0 <0.000013>
...

by strace read took almost 0.10 seconds..

Chaosty

unread,
Mar 1, 2010, 10:27:41 AM3/1/10
to memcached
sorry my bad full strace is:

0.000085 [28b4f1ab] gettimeofday({1667458660, 1681273911}, NULL)
= 0 <0.000013>
0.000202 [28b5f2a3] write(9, "set
b5e03d478da6b7b8e61095fec4eb0"..., 8196) = 8196 <0.000038>
0.000091 [28b5f2a3] write(9, "pr.parent_id = p.parent_id
(1)\";s"..., 1360) = 1360 <0.000023>
0.000078 [28b5f2c3] read(9, 0x2aef6054, 8196) = -1 EAGAIN
(Resource temporarily unavailable) <0.000014>
0.000061 [28b09d6f] poll([{fd=574240058, events=POLLIN|POLLPRI|
POLLRDNORM|POLLWRBAND|POLLERR|POLLNVAL|0x6000}], 1, INFTIM) = 1
([{fd=1933255265, revents=POLLIN|POLLPRI|POLLOUT|POLLHUP|POLLNVAL|
0x3a00}]) <0.098976>

0.099064 [28b5f2c3] read(9, "STORED\r\n"..., 8196) = 8 <0.000018>
0.000090 [28b4f1ab] gettimeofday({875772260, 912536929}, NULL) =
0 <0.000013>

dormando

unread,
Mar 1, 2010, 7:50:17 PM3/1/10
to memcached
What about memcached? Is it running on localhost or over the network?

Any chance you could get an strace from the memcached side? Have your test
app talk to a separate test instance or something.

Is it exactly or close to 0.10s each time? That's suspicious.

> > > > > ????????? public static function instance() {
> > > > > ????????? ????????? if (self::$instance === NULL) {
> > > > > ????????? ????????? ????????? // Create a new instance
> > > > > ????????? ????????? ????????? self::$instance = new Memcached ();
> > > > > ????????? ????????? ????????? self::$instance->setOption (Memcached::OPT_DISTRIBUTION, Memcached::DISTRIBUTION_CONSISTENT);
> > > > > ????????? ????????? ????????? self::$instance->addServers (array (array ('127.0.0.1', 11211, 100)));
> > > > > ????????? ????????? }
> > > > > ????????? }


> >
> > > > > and this is a set method that works fine with small data and stops with data > 100kbs
> >

> > > > > ????????? public static function set($key, $item, $exp = 60) {
> > > > > ????????? ????????? return self::$instance->set ($key, $item, $exp);
> > > > > ????????? }

Chaosty

unread,
Mar 1, 2010, 8:24:12 PM3/1/10
to memcached
It runs on the same server, php memcached connects by 127.0.0.1 to it.

it close but not the same. i did kill and run clean memcached server,
each time it was close to 0.1 sec.

I will do strace for memcached later and post the results.

On Mar 2, 3:50 am, dormando <dorma...@rydia.net> wrote:
> What about memcached? Is it running on localhost or over the network?
>
> Any chance you could get an strace from the memcached side? Have your test
> app talk to a separate test instance or something.
>
> Is it exactly or close to 0.10s each time? That's suspicious.
>
>
>
> On Mon, 1 Mar 2010, Chaosty wrote:
> > sorry my bad full strace is:
> >      0.000085 [28b4f1ab] gettimeofday({1667458660, 1681273911}, NULL)
> > = 0 <0.000013>
> >      0.000202 [28b5f2a3] write(9, "set
> > b5e03d478da6b7b8e61095fec4eb0"..., 8196) = 8196 <0.000038>
> >      0.000091 [28b5f2a3] write(9, "pr.parent_id = p.parent_id
> > (1)\";s"..., 1360) = 1360 <0.000023>
> >      0.000078 [28b5f2c3] read(9, 0x2aef6054, 8196) = -1 EAGAIN
> > (Resource temporarily unavailable) <0.000014>
> >      0.000061 [28b09d6f] poll([{fd=574240058, events=POLLIN|POLLPRI|
> > POLLRDNORM|POLLWRBAND|POLLERR|POLLNVAL|0x6000}], 1, INFTIM) = 1
> > ([{fd=1933255265, revents=POLLIN|POLLPRI|POLLOUT|POLLHUP|POLLNVAL|
> > 0x3a00}]) <0.098976>
> >      0.099064 [28b5f2c3] read(9, "STORED\r\n"..., 8196) = 8 <0.000018>
> >      0.000090 [28b4f1ab] gettimeofday({875772260, 912536929}, NULL) =
> > 0 <0.000013>
>

> > On Mar 1, 6:24�pm, Chaosty <chaostyz...@gmail.com> wrote:
> > > And here is strace
> > > ...

> > > � � �0.000085 [28b4f1ab] gettimeofday({1667458660, 1681273911}, NULL)
> > > = 0 <0.000013>
> > > � � �0.000202 [28b5f2a3] write(9, "set


> > > b5e03d478da6b7b8e61095fec4eb0"..., 8196) = 8196 <0.000038>

> > > � � �0.000091 [28b5f2a3] write(9, "pr.parent_id = p.parent_id


> > > (1)\";s"..., 1360) = 1360 <0.000023>

> > > � � �0.000078 [28b5f2c3] read(9, 0x2aef6054, 8196) = -1 EAGAIN
> > > (Resource temporarily unavailable) <0.000014>
> > > � � �0.000061 [28b09d6f] poll([{fd=574240058, events=POLLIN|POLLPRI|


> > > POLLRDNORM|POLLWRBAND|POLLERR|POLLNVAL|0x6000}], 1, INFTIM) = 1
> > > ([{fd=1933255265, revent$

> > > � � �0.099064 [28b5f2c3] read(9, "STORED\r\n"..., 8196) = 8 <0.000018>
> > > � � �0.000090 [28b4f1ab] gettimeofday({875772260, 912536929}, NULL) =
> > > 0 <0.000013>
> > > �...


>
> > > by strace read took almost 0.10 seconds..
>

> > > On Mar 1, 6:13�pm, Chaosty <chaostyz...@gmail.com> wrote:
>
> > > > The tests were performed by modifying the set method like this:
>

> > > > � � � � public static function set($key, $item, $exp = 60) {
> > > > � � � � � � � � $benchmark = Profiler::start ('Memory', 'Set: '. $key);
> > > > � � � � � � � � $return = self::$instance->set ($key, $item, $exp);
> > > > � � � � � � � � Profiler::stop ($benchmark);
> > > > � � � � � � � � return $return;
> > > > � � � � }


>
> > > > Then I figured out that almost each set is cost to us ~0.000079
> > > > seconds
> > > > but the big key costs ~0.099359 seconds
>
> > > > this is trace info with: truss -faedD -o /phplog
> > > > ...
> > > > 76982: 2.431621337 0.000014247 gettimeofday({1267456195.261569 },0x0)
> > > > = 0 (0x0)
> > > > 76982: 2.431709896 0.000014806 gettimeofday({1267456195.261658 },0x0)
> > > > = 0 (0x0)
> > > > 76982: 2.431964677 0.000045257 write(9,"set
> > > > b5e03d478da6b7b8e61095fec4eb"...,8196) = 8196 (0x2004)
> > > > 76982: 2.432037871 0.000017600 write(9,"pr.parent_id = p.parent_id
> > > > (1)";"...,1360) = 1360 (0x550)
> > > > 76982: 2.432097655 0.000015644 read(9,0x2aedb054,8196) ERR#35
> > > > 'Resource temporarily unavailable'
> > > > 76982: 2.532011750 0.099864927 poll({9/POLLIN},1,-1) = 1 (0x1)
> > > > 76982: 2.532070696 0.000016482 read(9,"STORED\r\n",8196) = 8 (0x8)
> > > > 76982: 2.532135509 0.000014248 gettimeofday({1267456195.362084 },0x0)
> > > > = 0 (0x0)
> > > > ...
> > > > seems here's the problem: 76982: 2.532011750 0.099864927 poll({9/
> > > > POLLIN},1,-1) = 1 (0x1)
>

> > > > On Feb 28, 3:41�am, dormando <dorma...@rydia.net> wrote:
>
> > > > > How are you performing the test? Is memcached over localhost or over the
> > > > > network?
>
> > > > > If you can reproduce this in isolation I'd be curious to see what
> > > > > memcached and/or php are waiting on that takes so long (via strace or
> > > > > similar).
>
> > > > > On Wed, 24 Feb 2010, me from wrote:
> > > > > > Adam we are on freebsd 7.2, as i said early we use PECL memcached 1.0.0 with libmemcached 0.35, the memcached version is 1.4.4.
>
> > > > > > We use our framework this is an init method
>
> > > > > > ????????? public static function instance() {
> > > > > > ????????? ????????? if (self::$instance === NULL) {
> > > > > > ????????? ????????? ????????? // Create a new instance
> > > > > > ????????? ????????? ????????? self::$instance = new Memcached ();
> > > > > > ????????? ????????? ????????? self::$instance->setOption (Memcached::OPT_DISTRIBUTION, Memcached::DISTRIBUTION_CONSISTENT);
> > > > > > ????????? ????????? ????????? self::$instance->addServers (array (array ('127.0.0.1', 11211, 100)));
> > > > > > ????????? ????????? }
> > > > > > ????????? }
>
> > > > > > and this is a set method that works fine with small data and stops with data > 100kbs
>
> > > > > > ????????? public static function set($key, $item, $exp = 60) {
> > > > > > ????????? ????????? return self::$instance->set ($key, $item, $exp);
> > > > > > ????????? }
>
> > > > > > Marc, no we don't use persistent you can see it in our init method.
>
> > > > > > On Wed, Feb 24, 2010 at 8:47 PM, Marc Bollinger <mbollin...@gmail.com> wrote:

> > > > > > � � � And are you using persistent connections? There have been a handful of
> > > > > > � � � threads recently, discussing setting up persistent connections with
> > > > > > � � � PECL::memcached.
>
> > > > > > � � � - Marc

Matt Ingenthron

unread,
Mar 1, 2010, 8:27:43 PM3/1/10
to memc...@googlegroups.com
Chaosty wrote:
> It runs on the same server, php memcached connects by 127.0.0.1 to it.
>
> it close but not the same. i did kill and run clean memcached server,
> each time it was close to 0.1 sec.
>

In that case, I totally agree this is suspicious.

Just to toss out another idea, it sounds like maybe the library/code
checking the response time doesn't have enough resolution, and it's
rounding up. 1/10th of a second is an odd place to stop resolution to
though. Bad multiplying or rounding?

I've seen people claim lots of 1ms responses when it turned out all of
the responses were in microseconds, they just didn't have enough resolution.

Chaosty

unread,
Mar 1, 2010, 8:49:22 PM3/1/10
to memcached
i would agree but trace shows delay:
this one by truss (freebsd strace)
76982: 2.532011750 0.099864927 poll({9/POLLIN},1,-1) = 1 (0x1) it
tooks 0.099seconds

and this one by strace


0.000061 [28b09d6f] poll([{fd=574240058, events=POLLIN|POLLPRI|
POLLRDNORM|POLLWRBAND|POLLERR|POLLNVAL|0x6000}], 1, INFTIM) = 1
([{fd=1933255265, revents=POLLIN|POLLPRI|POLLOUT|POLLHUP|POLLNVAL|
0x3a00}]) <0.098976>

also ~0.09 seconds.

both freezes on pool

Reply all
Reply to author
Forward
0 new messages