Re: [Sequoiadb-discuss] Request blocked forever in Sequoia

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 422-6466

Hi Emmanuel,

The problem occurs systematically, always at the same place with the  
same query stuck in the write scheduler queue.

There is no pending request on the MySQL backends. By the way, in  
order to simplify the configuration I removed one backend from the  
config, so now I use only one backend, and the results are identical.

Yes, both backends (now the single backend) are enabled.

I ran some tests with Alfresco connecting directly to MySQL instead of  
Sequoia. It is obviously successful. I made some traces using mysql  
"general_log" option to see all the queries that were generated during  
initialization. I compared with the contents of Sequoia Parsing Cache  
for the same initialization sequence. Doing so I noticed 2 things:
    1- The order of the queries is considerably different. The  
sequence contains several create table, alter table, create index, etc  
and was surprised to see that they were not executed in the same order.
    2- The query that blocks in Sequoia's write request queue is  
slightly different in Sequoia than in direct MySQL:
             In mysql: insert into alf_attributes (version, acl_id,  
type) values (0, null, 'M')
             In Sequoia: insert into alf_attributes (version, acl_id,  
type) values (?, ?, 'M') | <!%L|0|!%><!%N|-5|!%>

I tried to execute both queries in the SQL client in the Sequoia's  
console and I got this:
      jdbc:sequoia://localhost:25322/alfresco (alfresco) > insert into  
alf_attributes (version, acl_id, type) values (0, null, 'M');
      Affected rows: 1
      Query executed in 0 s 117 ms .

      jdbc:sequoia://localhost:25322/alfresco (alfresco) > insert into  
alf_attributes (version, acl_id, type) values (0, -5, 'M');
      An error occured while executing SQL query  
(org.continuent.sequoia.common.exceptions.driver.DriverSQLException:  
Message of cause: write request 322 failed:
      Backend alfresco - BackendWorkerThread for backend 'mysql1' with  
RAIDb level:1 failed (Cannot add or update a child row: a foreign key  
constraint fails (`alfresco`.`alf_attributes`,  
CONSTRAINT`fk_alf_attr_acl` FOREIGN KEY (`acl_id`) REFERENCES  
`alf_access_control_list` (`id`))))

Clearly the query in Sequoia's Parsing cache is wrong.

Here are my configs:

Controller:
------------
<?xml version="1.0" encoding="UTF-8" ?>

<!DOCTYPE SEQUOIA-CONTROLLER PUBLIC "-//Continuent//DTD SEQUOIA- 
CONTROLLER 2.10.10//EN"  "http://sequoia.continuent.org/dtds/sequoia-controller-2.10.10.dtd 
">

<SEQUOIA-CONTROLLER>
   <Controller ipAddress="0.0.0.0" port="25322">
     <Report hideSensitiveData="true" generateOnShutdown="true"  
generateOnFatal="true" enableFileLogging="true" />
     <JmxSettings>
       <RmiJmxAdaptor port="1090"/>
     </JmxSettings>
     <VirtualDatabase configFile="mysqltest-raidb1.xml"  
virtualDatabaseName="alfresco" autoEnableBackends="false"/>
   </Controller>
</SEQUOIA-CONTROLLER>

Virtual database:
--------------------

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE SEQUOIA PUBLIC "-//Continuent//DTD SEQUOIA 2.10.10//EN" "http://sequoia.continuent.org/dtds/sequoia-2.10.10.dtd 
">

<SEQUOIA>

   <VirtualDatabase name="alfresco">

<!--    <Distribution>
       <MessageTimeouts/>
	</Distribution>
-->	
     <Monitoring>
       <SQLMonitoring defaultMonitoring="off">
          <SQLMonitoringRule queryPattern="^select"  
caseSensitive="false" applyToSkeleton ="false" monitoring="on"/>
       </SQLMonitoring>
     </Monitoring>

     <Backup>
       <Backuper backuperName="Octopus"

className 
="org.continuent.sequoia.controller.backup.backupers.OctopusBackuper"
         options="zip=true"/>
     </Backup>

     <AuthenticationManager>
       <Admin>
        	<User username="admin" password=""/>
       </Admin>
       <VirtualUsers>
         <VirtualLogin vLogin="alfresco" vPassword="alfresco"/>
       </VirtualUsers>
     </AuthenticationManager>

     <DatabaseBackend name="mysql1" driver="com.mysql.jdbc.Driver"
       url="jdbc:mysql://localhost:3306/alfresco"
       connectionTestStatement="select 1">
       <ConnectionManager vLogin="alfresco" rLogin="testuser"  
rPassword="testuser">
         <VariablePoolConnectionManager initPoolSize="10"  
minPoolSize="5"
           maxPoolSize="50" idleTimeout="30" waitTimeout="10"/>
       </ConnectionManager>
     </DatabaseBackend>

<!--    <DatabaseBackend name="mysql2" driver="com.mysql.jdbc.Driver"
       url="jdbc:mysql://172.16.131.14:3306/alfresco"
       connectionTestStatement="select 1">
       <ConnectionManager vLogin="alfresco" rLogin="testuser"  
rPassword="testuser">
         <VariablePoolConnectionManager initPoolSize="40"  
minPoolSize="20"
           maxPoolSize="100" idleTimeout="30" waitTimeout="10"/>
       </ConnectionManager>
     </DatabaseBackend>
-->
     <RequestManager>
       <RequestScheduler>
<!--         <SingleDBScheduler level="pessimisticTransaction"/> -->
          <RAIDb-1Scheduler level="passThrough"/>
       </RequestScheduler>

       <RequestCache>
          <MetadataCache/>
          <ParsingCache/>		
       </RequestCache>

       <LoadBalancer>
          <RAIDb-1>
             <WaitForCompletion policy="all"/>
             <RAIDb-1-LeastPendingRequestsFirst/>
          </RAIDb-1>
       </LoadBalancer>

       <RecoveryLog driver="com.mysql.jdbc.Driver"
         url="jdbc:mysql://localhost:3306/sequoia? 
dumpQueriesOnException=true"
         login="testuser" password="testuser">
         <RecoveryLogTable
           tableName="RECOVERY"
           logIdColumnType="BIGINT NOT NULL"
           vloginColumnType="VARCHAR(26) NOT NULL"
           sqlColumnName="sqlStmt"
           sqlColumnType="VARCHAR(2048) NOT NULL"
           sqlParamColumnType="VARCHAR(8192)"
           extraStatementDefinition=",PRIMARY KEY (log_id)"/>
         <CheckpointTable tableName="CHECKPOINT"
           checkpointNameColumnType="VARCHAR(80) NOT NULL"/>
         <BackendTable tableName="BACKEND"
           databaseNameColumnType="VARCHAR(256) NOT NULL"
           backendNameColumnType="VARCHAR(256) NOT NULL"
           checkpointNameColumnType="VARCHAR(256) NOT NULL"/>
         <DumpTable tableName="DUMP"
           dumpNameColumnType="VARCHAR(256) NOT NULL"
           dumpDateColumnType="VARCHAR(100) NOT NULL"
           dumpPathColumnType="VARCHAR(512) NOT NULL"
           dumpFormatColumnType ="VARCHAR(8192) NOT NULL"
           checkpointNameColumnType="VARCHAR(8192) NOT NULL"
           backendNameColumnType="VARCHAR(8192) NOT NULL"
           tablesColumnType="VARCHAR(8192) NOT NULL"/>
       </RecoveryLog>
     </RequestManager>

   </VirtualDatabase>

</SEQUOIA>

Thanks for your help,

Richard Vigeant
Senior Software Developer
Vantrix

T +1 514-866-1717
M +1 438-275-2610
F +1 514-866-6868

ric...@va...
www.vantrix.com

On May 13, 2009, at 5:42 PM, Emmanuel Cecchet wrote:

> Hi Richard,
>
> Can you reproduce the problem systematically?
> Could you post your virtual database configuration file?
> As the request is executing, it might be blocked on a lock (that  
> would be a bug) or waiting for MySQL backends to complete (we would  
> then have to figure out why MySQL is blocked).
>
> Do you see any pending request on any MySQL backend (when you log  
> directly on MySQL)?
> Both backends show as enabled in Sequoia?
>
> Thanks for your feedback,
> Emmanuel
>
>> I encounter a strange problem when using Alfresco that uses  
>> Hibernate with Sequoia.
>> Sequoia is configured with 1 virtual database using 2 MySQL backends.
>> What happens is that when Alfresco first starts, it creates its  
>> tables successfully, then issues a number of SELECTS successfully  
>> and then issues a "INSERT" which gets stuck in Sequoia request  
>> queue forever.
>>
>> Is there anything I can do to find out what Sequoia is waiting for?
>>
>> Here are the details of the request:
>>
>> insert into alf_attributes (version, acl_id, type) values (?, ?,  
>> 'M'): Id=523, query=insert into alf_attributes (version, acl_id,  
>> type) values (?, ?, 'M'), params=<!%L|0|!%><!%N|-5|!%>, transaction  
>> id=324, persistent connection id=0
>>
>> alfresco(admin) > dump scheduler queues Active transactions: 1
>> +-----+-------------+
>> | tid   | time (in s) | +-----+-------------+
>> | 324 | 76247       | +-----+-------------+
>>
>> ----------------
>>
>> Pending read requests: 0
>> Read request id list:
>>
>> Pending write requests: 1
>> Write request id list:
>> 523
>>
>> ----------------
>>
>> alfresco(admin) > dump transaction 324
>> +--------+---------- 
>> + 
>> -----------------------------------------------------------------------+ 
>> -----------------------+----------------+---------------- 
>> +------------+-------------+-----------+--------------+
>> | log_id | vlogin   |  
>> sqlStmt 
>>                                                                |  
>> sqlStmt_param         | auto_conn_tran | transaction_id |  
>> request_id | exec_status | exec_time | update_count | +-------- 
>> +---------- 
>> + 
>> -----------------------------------------------------------------------+ 
>> -----------------------+----------------+---------------- 
>> +------------+-------------+-----------+--------------+
>> | 1      | alfresco |  
>> begin 
>>                                                                  |  
>> null                  | T              | 324            |  
>> 0          | S           | 0         | -1           | | 2      |  
>> alfresco | insert into alf_attributes (version, acl_id, type)  
>> values (?, ?, 'M') | <!%L|0|!%><!%N|-5|!%> | T              |  
>> 324            | 523        | E           | 2         |  
>> 0            | +--------+---------- 
>> + 
>> -----------------------------------------------------------------------+ 
>> -----------------------+----------------+---------------- 
>> +------------+-------------+-----------+--------------+
>>
>> ----------------
>> alfresco(admin) > dump request 523
>> Request id: 523
>>   query: insert into alf_attributes (version, acl_id, type) values  
>> (?, ?, 'M')
>>   parameters: <!%L|0|!%><!%N|-5|!%>
>>   login: alfresco
>>   autocommit: false
>>   transaction id: 324
>>   cacheable status: CACHEABLE
>>   isolation level: TRANSACTION_UNDEFINED
>>   start time: 1242150743853
>>   end time: 0
>>   timeout in seconds: 0
>>   locked tables:
>>      alf_attributes
>>   persistent connection id: 0
>>   client ip address: /127.0.0.1
>>
>>
>> Thanks for any help.
>>
>> Richard Vigeant
>>
>> ------------------------------------------------------------------------
>>
>> ------------------------------------------------------------------------------
>> The NEW KODAK i700 Series Scanners deliver under ANY circumstances!  
>> Your
>> production scanning environment may not be a perfect world - but  
>> thanks to
>> Kodak, there's a perfect scanner to get the job done! With the NEW  
>> KODAK i700
>> Series Scanner you'll get full speed at 300 dpi even with all image  
>> processing features enabled. http://p.sf.net/sfu/kodak-com
>> ------------------------------------------------------------------------
>>
>> _______________________________________________
>> Sequoiadb-discuss mailing list
>> Seq...@li...
>> https://lists.sourceforge.net/lists/listinfo/sequoiadb-discuss
>>
>
>
> -- 
> Emmanuel Cecchet
> FTO @ Frog Thinker Open Source Development & Consulting
> --
> Web: http://www.frogthinker.org
> email: ma...@fr...
> Skype: emmanuel_cecchet
>