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

[Chris Stromsoe]

In case anybody else is having the same problem -- I am working around 
this problem by using the post authentication hook to check for the 
existing of the default share for kronolith and nag and am creating them 
if they don't.  I am not using the shares API, since that's what I'm 
having problems with.

I'd prefer to fix the problem described below, but I don't have much more 
time to invest in tracking this down.  In the mean time, his is my hook. 
If anybody can think of a cleaner way to do this, I'm all ears.


-Chris

function _horde_hook_postauthenticate($userID, $credential, $realm)
{
     global $conf;

     require_once 'DB.php';

     $db =& DB::connect($conf['sql'], true);
     if (PEAR::isError($db)) {
         Horde::logMessage("db connection: " . $db->getMessage(), __FILE__, __LINE__, PHP_LOG_ERR);
         return false;
     }

     $shares = array('kronolith' => 'Default Calendar',
                     'mnemo' => 'Default Notepad',
                     'nag' => 'Default Task List');

     foreach ($shares as $group => $name) {
         $group = 'horde.shares.' . $group;

         $query = sprintf("SELECT datatree_id FROM horde_datatree " .
                          "WHERE user_uid = %s AND group_uid = '%s';",
                          $db->quote($userID), $group);
         $rows = $db->getAll($query);

         if (count($rows) == 0) {
             $db->autoCommit(false);

             $query = "SELECT NEXTVAL('horde_datatree_seq');";
             $sequence = $db->getOne($query);
             if (count($sequence) != 1) {
                 $db->rollback();
                 $db->disconnect();
                 return false;
             }

             $query = "INSERT INTO horde_datatree_attributes " .
                      "(datatree_id,attribute_name,attribute_key,attribute_value) ".
                      "VALUES (?, ?, ?, ?);";
             $sth = $db->prepare($query);
             if (PEAR::isError($db->execute($sth, array($sequence, "owner", "", $userID))) ||
                 PEAR::isError($db->execute($sth, array($sequence, "name", "", $name))) ||
                 PEAR::isError($db->execute($sth, array($sequence, "perm_type", "", "matrix"))) ||
                 PEAR::isError($db->execute($sth, array($sequence, "perm_users", $userID, "30")))
             ) {
                 Horde::logMessage("db connection: " . $db->getMessage(), __FILE__, __LINE__, PHP_LOG_ERR);
                 $db->rollback();
                 $db->disconnect();
                 return false;
             }

             $query = "INSERT INTO horde_datatree " .
                     "(datatree_id,group_uid,user_uid,datatree_name,datatree_parents,datatree_serialized) " .
                     "VALUES (?, ?, ?, ?, ?, ?);";
             $sth = $db->prepare($query);
             $rc = $db->execute($sth, array($sequence, $group, $userID, $userID, '', 0));
             if (PEAR::isError($rc)) {

             Horde::logMessage("db connection: " . $db->getMessage(), __FILE__, __LINE__, PHP_LOG_ERR);
                 $db->rollback();
                 $db->disconnect();
                 return false;
             }

             $db->commit();
             $db->autoCommit(true);
         }
     }
     $db->disconnect();

         return true;
}



On Sat, 30 Dec 2006, Chris Stromsoe wrote:

> 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
>>> 
>> 
>