[horde] php and postgres, Re: Horde 3.1, memcache sessionhandler, sidebar, and flock()

[Chris Stromsoe]

The more I look at this, the more it looks like here is either something 
broken in the way that PHP is interacting with postgres, or there is 
something broken in the way that horde is using DB to interact with 
postgres.

The first call to ->exists() for any share returns quickly.  Subsequent 
calls to ->exists() take an enormous amount of time.

I've inserted microtime() calls into the PEAR DB code in fetchInto(), 
around pg_fetch_row().

During the first exists() call, all of the calls to pg_fetch_row() return 
almost right away (multiple calls return with the same time value, 
measured to one microsecond).

For calls to exists() afterward, the first 12 to 16 calls to 
pg_fetch_row() return in the same amount of time as the first call to 
exists().  All calls after that point average > 100ms to return.

The first calendar access calls exists() to check for a calendar.  If one 
does not exists, it creates a share.  addShare() calls exists(), running 
175s (~13k items at 120+ms each).  I'm adding nag events to calendars. 
Since people who don't have a calendar likely also don't have a tasklist, 
addShares() gets called again, looping over 24500 nag shares.


In any event, I'm stumped about where to look.  Is anybody else using 
postgres and shares/datatree seeing the same issues (extremely long lag 
times to create the first instance of a share) ?

This is happening for me with both kronolith and nag.  I have not checked 
other applications at this point.



-Chris


On Sat, 30 Dec 2006, Chris Stromsoe wrote:
> On Sat, 30 Dec 2006, Chris Stromsoe wrote:
>> On Sat, 30 Dec 2006, Chris Stromsoe wrote:
>> 
>>> The call to "$GLOBALS['kronolith_shares']->addShare($share);" returns the 
>>> results of "$this->_datatree->add($share);"
>>> 
>>> That calls exists() from DataTree.php, which calls _load() from 
>>> DataTree/sql.php.  _load() runs the query
>>>
>>>  SELECT c.datatree_id, c.datatree_name, c.datatree_parents,
>>>         c.datatree_order
>>>  FROM horde_datatree c
>>>  WHERE c.group_uid = 'horde.shares.kronolith'
>>> 
>>> and then calls DB::getAll(), which loads the results by looping over all 
>>> 13,000+ of the entries.  I added time() calls into DB/common.php around 
>>> the block that loops loading the rows, and I'm timing it at 175s to 
>>> complete.
>> 
>> 
>> Now I'm really confused.  The code block in base.php that I'm looking at 
>> looks like this:
>>
>>        /* If the user's personal calendar doesn't exist, then create it. */
>> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>>        if (!$GLOBALS['kronolith_shares']->exists(Auth::getAuth())) {
>> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>>            require_once 'Horde/Identity.php';
>>            $identity = &Identity::singleton();
>>            $name = $identity->getValue('fullname');
>>            if (trim($name) == '') {
>>                $name = Auth::removeHook(Auth::getAuth());
>>            }
>>
>>            $share = 
>> &$GLOBALS['kronolith_shares']->newShare(Auth::getAuth());
>>            $share->set('name', sprintf(_("%s's Calendar"), $name));
>> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>>            $GLOBALS['kronolith_shares']->addShare($share);
>> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>>            $GLOBALS['all_calendars'][Auth::getAuth()] = &$share;
>> 
>> 
>> The call to ->exists goes through the above mentioned code path.  It runs 
>> the same query and loads the same 13k+ entries.  It completes in 2s 
>> according to the elapsed time() calls.
>> 
>> The call to ->addShare() ends up calling ->exists(), which runs the above 
>> query.  Only it takes 175s to complete.  I added additional time() logging 
>> into the getAll() from PEAR DB to verify.
>> 
>> 
>> If I add more calls to ->exists, for example, changing the code to read:
>>
>>        /* If the user's personal calendar doesn't exist, then create it. */
>> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>>        if (!$GLOBALS['kronolith_shares']->exists(Auth::getAuth())) {
>> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>> $GLOBALS['kronolith_shares']->exists(Auth::getAuth());
>> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>>
>>            require_once 'Horde/Identity.php';
>>            $identity = &Identity::singleton();
>>            $name = $identity->getValue('fullname');
>>            if (trim($name) == '') {
>>                $name = Auth::removeHook(Auth::getAuth());
>>            }
>>
>>            $share = 
>> &$GLOBALS['kronolith_shares']->newShare(Auth::getAuth());
>>            $share->set('name', sprintf(_("%s's Calendar"), $name));
>> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>>            $GLOBALS['kronolith_shares']->addShare($share);
>> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>>            $GLOBALS['all_calendars'][Auth::getAuth()] = &$share;
>> 
>
>
> One final oddity:
>
> If I remove the first explicit call to ->exists() and change the code so that 
> it reads:
>
>
>       /* If the user's personal calendar doesn't exist, then create it. */
> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>       if (1) {
> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>           require_once 'Horde/Identity.php';
>           $identity = &Identity::singleton();
>           $name = $identity->getValue('fullname');
>           if (trim($name) == '') {
>               $name = Auth::removeHook(Auth::getAuth());
>           }
>
>           $share = &$GLOBALS['kronolith_shares']->newShare(Auth::getAuth());
>           $share->set('name', sprintf(_("%s's Calendar"), $name));
> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>           $GLOBALS['kronolith_shares']->addShare($share);
> Horde::logMessage("time " . time(), __FILE__, __LINE__, PEAR_LOG_ERR);
>           $GLOBALS['all_calendars'][Auth::getAuth()] = &$share;
>
>
> to unconditionally run the block, ->addShares() returns in 37s instead of 
> 175s.
>
>
>
>
>
>
> -Chris
>
>
>
>> 
>> 
>> Inserting the additional call to ->exists() adds another 175s to the call 
>> time.
>> 
>> 
>> I've built a stand-alone file using DB to execute the same query, but can't 
>> duplicate the behavior.
>> 
>> For reference, this is horde stable, kronolith stable, postgres 8.2, php 
>> 5.2.0, and DB 1.7.6.  I am not familiar enough with the PEAR DB code, let 
>> alone how horde is using it to know where to look next.  Any ideas?
>> 
>> 
>> 
>> -Chris
>> 
>