[horde] Horde 3.1, memcache sessionhandler, sidebar, and flock()

[Chris Stromsoe]

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;



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