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

[Chris Stromsoe]

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
>