Re: [ZODB-Dev] Problem with RelStorage zodbpack
On 03/29/2011 09:16 PM, Erik Dahl wrote: Ok looked a little deeper. I think solution 2 is the way to go (ie clear the object_ref table from references that are in my range of non-packed transactions. Does that sound right? Statement would be: delete from object_ref where tid 255908476364112230; I think once this is done the code will refill the table and go on its way. Thoughts? I haven't read the whole thread, but I will say this: it is quite safe to remove rows from object_ref as long as you *also* remove the corresponding rows from object_refs_added. To be 100% safe, you could just clear both object_refs_added and object_ref before packing. IOW, the object_ref table serves as a cache between pack operations and the object_refs_added table indicates how much of the object_ref cache is filled. Shane ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org https://mail.zope.org/mailman/listinfo/zodb-dev
Re: [ZODB-Dev] Problem with RelStorage zodbpack
On 03/29/2011 07:39 PM, Erik Dahl wrote: I was running a pack and canceled so that I could reboot my box. After it came back up I tried to restart the pack and got this: [...] File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py, line 397, in _add_refs_for_tid self.runner.run_many(cursor, stmt, add_rows) [...] IntegrityError: (1062, Duplicate entry '255911127406517196-2714-893440' for key 'PRIMARY') Ah, I recognize this now. This is a minor bug that I believe has been fixed for 1.5.0. It only affects packing; it has zero impact on your application. The bug occurs when filling the object_ref table for packing. If you interrupt the pack operation while the object_ref table is being filled, the corresponding entry in object_refs_added will not be created and the next attempt to pack will try again and stumble in exactly this way. The bug has been solved by replacing entries in object_ref rather than just inserting them. The object_ref and object_refs_added tables are only used during packing. Perhaps the quickest thing to do is remove only the offending entries: delete from object_refs_added where tid = 255911127406517196; delete from object_ref where tid = 255911127406517196; A bit of trivia: that error message says that object 2714 in transaction 255911127406517196 has at least one direct reference to object 893440. Shane ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org https://mail.zope.org/mailman/listinfo/zodb-dev
Re: [ZODB-Dev] Problem with RelStorage zodbpack
Shane, Thanks for the quick response and the great tool! I brought the app back up last night when I realized that this was primarily related to packing. I'll give this a shot tonight when the app is quiet and I can run a pack. -EAD On Mar 30, 2011, at 12:34 PM, Shane Hathaway wrote: On 03/29/2011 07:39 PM, Erik Dahl wrote: I was running a pack and canceled so that I could reboot my box. After it came back up I tried to restart the pack and got this: [...] File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py, line 397, in _add_refs_for_tid self.runner.run_many(cursor, stmt, add_rows) [...] IntegrityError: (1062, Duplicate entry '255911127406517196-2714-893440' for key 'PRIMARY') Ah, I recognize this now. This is a minor bug that I believe has been fixed for 1.5.0. It only affects packing; it has zero impact on your application. The bug occurs when filling the object_ref table for packing. If you interrupt the pack operation while the object_ref table is being filled, the corresponding entry in object_refs_added will not be created and the next attempt to pack will try again and stumble in exactly this way. The bug has been solved by replacing entries in object_ref rather than just inserting them. The object_ref and object_refs_added tables are only used during packing. Perhaps the quickest thing to do is remove only the offending entries: delete from object_refs_added where tid = 255911127406517196; delete from object_ref where tid = 255911127406517196; A bit of trivia: that error message says that object 2714 in transaction 255911127406517196 has at least one direct reference to object 893440. Shane ___ For more information about ZODB, see the ZODB Wiki: http://www.zope.org/Wikis/ZODB/ ZODB-Dev mailing list - ZODB-Dev@zope.org https://mail.zope.org/mailman/listinfo/zodb-dev
Re: [ZODB-Dev] Problem with RelStorage zodbpack
Ok I'm starting to understand things a little better. The transaction 255911127406517196 was the last transaction who's references were added to the object_ref table. But (I'm guessing because I interrupted the pack) it didn't get marked in the transaction table as packed. In fact there are 11088 transactions in this state. Below are the details. I haven't fully understood the code yet (and its getting too late for productive thinking :) ) but I see to potential solutions: 1. Mark the transactions that have been moved to object_ref as packed but I'm guessing though that this isn't a good idea because there is other stuff that needs to happen during the pack. 2. Remove the unpacked transactions from the object_ref table. (this seems very scary to me). I will continue looking at the code tomorrow. In the mean time is there an issue with continuing to use the database? Will the orphaned object_ref records cause a problem. (doesn't seem like they would). Here are the details: mysql select tid from transaction where tid = 255911127406517196 and packed=true order by tid desc limit 1; ++ | tid| ++ | 255908476364112230 | -- the last transaction marked as packed ++ mysql select count(*) from transaction where tid = 255908476364112230 and tid 255911127406517196 order by tid desc; +--+ | count(*) | +--+ |11088 | -- this is the number of transactions that seem to have been packed without being marked as packed. +--+ mysql select count(*) from transaction where tid 255911127406517196; +--+ | count(*) | +--+ | 178909 | -- number of transactions that haven't made it into the object_ref table +--+ mysql select count(*) from object_ref where tid 255911127406517196; +--+ | count(*) | +--+ |0 | -- confirmation that the transactions after 255911127406517196 have not made it into the object_ref table +--+ 1 row in set (0.00 sec) mysql select count(*) from object_ref where tid = 255911127406517196; +--+ | count(*) | +--+ | 3907 | -- confirmation again +--+ 1 row in set (0.00 sec) mysql select count(*) from object_ref where tid = 255911127406517196; +--+ | count(*) | +--+ | 3907 | -- and again +--+ 1 row in set (0.00 sec) -EAD On Mar 29, 2011, at 9:39 PM, Erik Dahl wrote: I was running a pack and canceled so that I could reboot my box. After it came back up I tried to restart the pack and got this: 2011-03-29 20:53:07,259 [zodbpack] INFO Opening storage (RelStorageFactory)... 2011-03-29 20:53:07,457 [zodbpack] INFO Packing storage (RelStorageFactory). 2011-03-29 20:53:07,464 [relstorage] INFO pack: analyzing transactions committed Tue Mar 29 20:49:48 2011 or before 2011-03-29 20:53:07,465 [relstorage.adapters.packundo] INFO pre_pack: start with gc enabled 2011-03-29 20:53:08,846 [relstorage.adapters.packundo] INFO discovering references from objects in 178910 transaction(s) 2011-03-29 20:53:10,808 [relstorage.adapters.packundo] ERROR pre_pack: failed Traceback (most recent call last): File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py, line 431, in pre_pack conn, cursor, pack_tid, get_references) File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py, line 525, in _pre_pack_with_gc self.fill_object_refs(conn, cursor, get_references) File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py, line 347, in fill_object_refs added += self._add_refs_for_tid(cursor, tid, get_references) File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py, line 397, in _add_refs_for_tid self.runner.run_many(cursor, stmt, add_rows) File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/scriptrunner.py, line 90, in run_many cursor.executemany(stmt, items) File build/bdist.linux-x86_64/egg/MySQLdb/cursors.py, line 206, in executemany r = r + self.execute(query, a) File build/bdist.linux-x86_64/egg/MySQLdb/cursors.py, line 174, in execute self.errorhandler(self, exc, value) File build/bdist.linux-x86_64/egg/MySQLdb/connections.py, line 36, in defaulterrorhandler raise errorclass, errorvalue IntegrityError: (1062, Duplicate entry '255911127406517196-2714-893440' for key 'PRIMARY') Traceback (most recent call last): File /opt/zenoss/bin/zodbpack, line 8, in module load_entry_point('RelStorage==1.4.2', 'console_scripts', 'zodbpack')() I'm in process of running mysqlcheck against the database and I have the application off line. I've looked at the code but I'm not 100% what it's trying to do. Thoughts? Is my database hosed? or just my packing process.
Re: [ZODB-Dev] Problem with RelStorage zodbpack
Ok looked a little deeper. I think solution 2 is the way to go (ie clear the object_ref table from references that are in my range of non-packed transactions. Does that sound right? Statement would be: delete from object_ref where tid 255908476364112230; I think once this is done the code will refill the table and go on its way. Thoughts? -EAD On Mar 29, 2011, at 11:00 PM, Erik Dahl wrote: Ok I'm starting to understand things a little better. The transaction 255911127406517196 was the last transaction who's references were added to the object_ref table. But (I'm guessing because I interrupted the pack) it didn't get marked in the transaction table as packed. In fact there are 11088 transactions in this state. Below are the details. I haven't fully understood the code yet (and its getting too late for productive thinking :) ) but I see to potential solutions: 1. Mark the transactions that have been moved to object_ref as packed but I'm guessing though that this isn't a good idea because there is other stuff that needs to happen during the pack. 2. Remove the unpacked transactions from the object_ref table. (this seems very scary to me). I will continue looking at the code tomorrow. In the mean time is there an issue with continuing to use the database? Will the orphaned object_ref records cause a problem. (doesn't seem like they would). Here are the details: mysql select tid from transaction where tid = 255911127406517196 and packed=true order by tid desc limit 1; ++ | tid| ++ | 255908476364112230 | -- the last transaction marked as packed ++ mysql select count(*) from transaction where tid = 255908476364112230 and tid 255911127406517196 order by tid desc; +--+ | count(*) | +--+ |11088 | -- this is the number of transactions that seem to have been packed without being marked as packed. +--+ mysql select count(*) from transaction where tid 255911127406517196; +--+ | count(*) | +--+ | 178909 | -- number of transactions that haven't made it into the object_ref table +--+ mysql select count(*) from object_ref where tid 255911127406517196; +--+ | count(*) | +--+ |0 | -- confirmation that the transactions after 255911127406517196 have not made it into the object_ref table +--+ 1 row in set (0.00 sec) mysql select count(*) from object_ref where tid = 255911127406517196; +--+ | count(*) | +--+ | 3907 | -- confirmation again +--+ 1 row in set (0.00 sec) mysql select count(*) from object_ref where tid = 255911127406517196; +--+ | count(*) | +--+ | 3907 | -- and again +--+ 1 row in set (0.00 sec) -EAD On Mar 29, 2011, at 9:39 PM, Erik Dahl wrote: I was running a pack and canceled so that I could reboot my box. After it came back up I tried to restart the pack and got this: 2011-03-29 20:53:07,259 [zodbpack] INFO Opening storage (RelStorageFactory)... 2011-03-29 20:53:07,457 [zodbpack] INFO Packing storage (RelStorageFactory). 2011-03-29 20:53:07,464 [relstorage] INFO pack: analyzing transactions committed Tue Mar 29 20:49:48 2011 or before 2011-03-29 20:53:07,465 [relstorage.adapters.packundo] INFO pre_pack: start with gc enabled 2011-03-29 20:53:08,846 [relstorage.adapters.packundo] INFO discovering references from objects in 178910 transaction(s) 2011-03-29 20:53:10,808 [relstorage.adapters.packundo] ERROR pre_pack: failed Traceback (most recent call last): File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py, line 431, in pre_pack conn, cursor, pack_tid, get_references) File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py, line 525, in _pre_pack_with_gc self.fill_object_refs(conn, cursor, get_references) File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py, line 347, in fill_object_refs added += self._add_refs_for_tid(cursor, tid, get_references) File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/packundo.py, line 397, in _add_refs_for_tid self.runner.run_many(cursor, stmt, add_rows) File /opt/zenoss/lib/python2.6/site-packages/RelStorage-1.4.2-py2.6.egg/relstorage/adapters/scriptrunner.py, line 90, in run_many cursor.executemany(stmt, items) File build/bdist.linux-x86_64/egg/MySQLdb/cursors.py, line 206, in executemany r = r + self.execute(query, a) File build/bdist.linux-x86_64/egg/MySQLdb/cursors.py, line 174, in execute self.errorhandler(self, exc, value) File build/bdist.linux-x86_64/egg/MySQLdb/connections.py, line 36, in defaulterrorhandler raise errorclass, errorvalue IntegrityError: