Alembic: Alembic 1.6.x hangs with 100% CPU usage
Describe the bug
~/code/projects/riparias/ alembic -c dev.ini upgrade heads
2021-05-17 13:24:05,775 INFO [sqlalchemy.engine.base.Engine][MainThread] select version()
2021-05-17 13:24:05,775 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:24:05,780 INFO [sqlalchemy.engine.base.Engine][MainThread] select current_schema()
2021-05-17 13:24:05,780 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:24:05,784 INFO [sqlalchemy.engine.base.Engine][MainThread] SELECT CAST('test plain returns' AS VARCHAR(60)) AS anon_1
2021-05-17 13:24:05,784 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:24:05,786 INFO [sqlalchemy.engine.base.Engine][MainThread] SELECT CAST('test unicode returns' AS VARCHAR(60)) AS anon_1
2021-05-17 13:24:05,787 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:24:05,788 INFO [sqlalchemy.engine.base.Engine][MainThread] show standard_conforming_strings
2021-05-17 13:24:05,788 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:24:05,796 INFO [sqlalchemy.engine.base.Engine][MainThread] BEGIN (implicit)
2021-05-17 13:24:05,798 INFO [sqlalchemy.engine.base.Engine][MainThread] select relname from pg_class c join pg_namespace n on n.oid=c.relnamespace where pg_catalog.pg_table_is_visible(c.oid) and relname=%(name)s
2021-05-17 13:24:05,798 INFO [sqlalchemy.engine.base.Engine][MainThread] {'name': 'alembic_version'}
2021-05-17 13:24:05,802 INFO [sqlalchemy.engine.base.Engine][MainThread] select relname from pg_class c join pg_namespace n on n.oid=c.relnamespace where pg_catalog.pg_table_is_visible(c.oid) and relname=%(name)s
2021-05-17 13:24:05,802 INFO [sqlalchemy.engine.base.Engine][MainThread] {'name': 'alembic_version'}
2021-05-17 13:24:05,806 INFO [sqlalchemy.engine.base.Engine][MainThread]
CREATE TABLE alembic_version (
version_num VARCHAR(32) NOT NULL,
CONSTRAINT alembic_version_pkc PRIMARY KEY (version_num)
)
2021-05-17 13:24:05,806 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
then it hangs with 100% CPU usage.
On the PosgreSQL side the query is in an "idle in transaction".
This is the alembic section in my dev.ini file:
[alembic]
script_location = riparias/alembic
file_template = %%(year)d%%(month).2d%%(day).2d_%%(rev)s_%%(slug)s
version_locations = amnesia:alembic/versions amnesia_multilingual:alembic/versions riparias/alembic/versions
Expected behavior
~/code/projects/riparias/ pip install alembic==1.5.8
Collecting alembic==1.5.8
Using cached alembic-1.5.8-py2.py3-none-any.whl (159 kB)
Requirement already satisfied: Mako in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from alembic==1.5.8) (1.1.4)
Requirement already satisfied: SQLAlchemy>=1.3.0 in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from alembic==1.5.8) (1.3.24)
Requirement already satisfied: python-dateutil in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from alembic==1.5.8) (2.8.1)
Requirement already satisfied: python-editor>=0.3 in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from alembic==1.5.8) (1.0.4)
Requirement already satisfied: MarkupSafe>=0.9.2 in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from Mako->alembic==1.5.8) (2.0.0)
Requirement already satisfied: six>=1.5 in /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages (from python-dateutil->alembic==1.5.8) (1.11.0)
Installing collected packages: alembic
Attempting uninstall: alembic
Found existing installation: alembic 1.6.2
Uninstalling alembic-1.6.2:
Successfully uninstalled alembic-1.6.2
Successfully installed alembic-1.5.8
~/code/projects/riparias/ alembic -c dev.ini upgrade heads
2021-05-17 13:27:35,420 INFO [sqlalchemy.engine.base.Engine][MainThread] select version()
2021-05-17 13:27:35,421 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:35,425 INFO [sqlalchemy.engine.base.Engine][MainThread] select current_schema()
2021-05-17 13:27:35,426 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:35,429 INFO [sqlalchemy.engine.base.Engine][MainThread] SELECT CAST('test plain returns' AS VARCHAR(60)) AS anon_1
2021-05-17 13:27:35,429 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:35,431 INFO [sqlalchemy.engine.base.Engine][MainThread] SELECT CAST('test unicode returns' AS VARCHAR(60)) AS anon_1
2021-05-17 13:27:35,432 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:35,432 INFO [sqlalchemy.engine.base.Engine][MainThread] show standard_conforming_strings
2021-05-17 13:27:35,433 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:35,441 INFO [sqlalchemy.engine.base.Engine][MainThread] BEGIN (implicit)
2021-05-17 13:27:35,442 INFO [sqlalchemy.engine.base.Engine][MainThread] select relname from pg_class c join pg_namespace n on n.oid=c.relnamespace where pg_catalog.pg_table_is_visible(c.oid) and relname=%(name)s
2021-05-17 13:27:35,443 INFO [sqlalchemy.engine.base.Engine][MainThread] {'name': 'alembic_version'}
2021-05-17 13:27:35,447 INFO [sqlalchemy.engine.base.Engine][MainThread] select relname from pg_class c join pg_namespace n on n.oid=c.relnamespace where pg_catalog.pg_table_is_visible(c.oid) and relname=%(name)s
2021-05-17 13:27:35,447 INFO [sqlalchemy.engine.base.Engine][MainThread] {'name': 'alembic_version'}
2021-05-17 13:27:35,451 INFO [sqlalchemy.engine.base.Engine][MainThread]
CREATE TABLE alembic_version (
version_num VARCHAR(32) NOT NULL,
CONSTRAINT alembic_version_pkc PRIMARY KEY (version_num)
)
2021-05-17 13:27:35,451 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
===>>> Executing /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/amnesia/alembic/sql/upgrade/20191022_e025de45166e_init.sql
(...)
`2021-05-17 13:27:35,502 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:36,414 INFO [sqlalchemy.engine.base.Engine][MainThread] INSERT INTO alembic_version (version_num) VALUES ('e025de45166e') RETURNING alembic_version.version_num
2021-05-17 13:27:36,414 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
===>>> Executing /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/amnesia_multilingual/alembic/sql/upgrade/20200827_d9af39cf38ae_create_multilingual_branch.sql
(...)
2021-05-17 13:27:36,556 INFO [sqlalchemy.engine.base.Engine][MainThread] UPDATE alembic_version SET version_num='d9af39cf38ae' WHERE alembic_version.version_num = 'e025de45166e'
2021-05-17 13:27:36,557 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
===>>> Executing /usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/amnesia/alembic/sql/upgrade/20210503_32b12866f6a2_permissions.sql
2021-05-17 13:27:36,562 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:36,569 INFO [sqlalchemy.engine.base.Engine][MainThread] INSERT INTO alembic_version (version_num) VALUES ('32b12866f6a2') RETURNING alembic_version.version_num
2021-05-17 13:27:36,570 INFO [sqlalchemy.engine.base.Engine][MainThread] {}
2021-05-17 13:27:36,571 INFO [sqlalchemy.engine.base.Engine][MainThread] COMMIT
To Reproduce
Not sure.. but I'm using the following pattern in my versions/ path:
from pathlib import Path
from alembic import op
import sqlalchemy as sa
# revision identifiers, used by Alembic.
revision = 'e025de45166e'
down_revision = None
branch_labels = ('amnesiacms', )
depends_on = None
migration_path = Path(__file__)
migration_sql_path = migration_path.parent.parent / 'sql'
migration_sql_file = migration_path.with_suffix('.sql').name
upgrade_sql = migration_sql_path / 'upgrade' / migration_sql_file
downgrade_sql = migration_sql_path / 'downgrade' / migration_sql_file
def upgrade():
print('===>>> Executing ', upgrade_sql)
with open(upgrade_sql, 'r') as fp:
op.execute(fp.read())
def downgrade():
print('===>>> Executing ', downgrade_sql)
with open(downgrade_sql, 'r') as fp:
op.execute(fp.read())
Error
No errors, the process hangs at 100% CPU and the query stays in idle in transaction on the PostgreSQL side.
Versions.
- OS: FreeBSD 12.2-RELEASE
- Python: 3.7.9
- Alembic: 1.6.2
- SQLAlchemy: 1.3.24
- Database: PostgreSQL 13
- DBAPI: psycopg2 2.8.5
Additional context
Have a nice day!
silenius
All 16 comments
Thanks for reporting - are you able to share the revision tree somehow?
Also, does
alembic upgrade --sql base:heads
hang in 1.6.x or produce valid SQL output?
simonbowly
on 17 May 2021
alembic upgrade --sql base:heads hangs too:
~/code/projects/riparias/ alembic -c dev.ini upgrade --sql base:heads
BEGIN;
^CTraceback (most recent call last):
File "/usr/home/julien/code/venvs/riparias/bin/alembic", line 8, in <module>
sys.exit(main())
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/config.py", line 559, in main
CommandLine(prog=prog).main(argv=argv)
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/config.py", line 553, in main
self.run_cmd(cfg, options)
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/config.py", line 533, in run_cmd
**dict((k, getattr(options, k, None)) for k in kwarg)
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/command.py", line 294, in upgrade
script.run_env()
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/script/base.py", line 490, in run_env
util.load_python_file(self.dir, "env.py")
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/util/pyfiles.py", line 97, in load_python_file
module = load_module_py(module_id, path)
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/util/compat.py", line 182, in load_module_py
spec.loader.exec_module(module)
File "<frozen importlib._bootstrap_external>", line 728, in exec_module
File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
File "riparias/alembic/env.py", line 56, in <module>
run_migrations_offline()
File "riparias/alembic/env.py", line 30, in run_migrations_offline
context.run_migrations()
File "<string>", line 8, in run_migrations
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/runtime/environment.py", line 813, in run_migrations
self.get_context().run_migrations(**kw)
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/runtime/migration.py", line 549, in run_migrations
for step in self._migrations_fn(heads, self):
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/command.py", line 283, in upgrade
return script._upgrade_revs(revision, rev)
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/script/base.py", line 365, in _upgrade_revs
revs = list(revs)
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/script/revision.py", line 714, in iterate_revisions
for node in self._topological_sort(revisions, heads):
File "/usr/home/julien/code/venvs/riparias/lib/python3.7/site-packages/alembic/script/revision.py", line 846, in _topological_sort
for check_head_index, ancestors in enumerate(ancestors_by_idx):
KeyboardInterrupt
This is the history on 1.5.8 (the command hangs on 1.6.2):
~/code/projects/riparias/ alembic -c dev.ini history
e025de45166e (e025de45166e) -> 32b12866f6a2 (amnesiacms) (head), permissions
<base> (e025de45166e) -> d9af39cf38ae (multilingual) (head), create multilingual branch
<base> -> e025de45166e (amnesiacms), init
I don't know if it can help, but the full alembic/ are available from https://github.com/silenius/amnesia/tree/dev/amnesia/alembic for the amnesiacms branch and from https://github.com/silenius/amnesia_multilingual/tree/dev/amnesia_multilingual/alembic for the multilingual branch
silenius
on 17 May 2021
Awesome, thanks. Looks like it's somehow related to repeating an identifier in depends_on that's already the down_revision for that script (like below). I think it's not needed to repeat the dependency but alembic should handle it. Will look into it!
revision = '32b12866f6a2'
down_revision = 'e025de45166e'
branch_labels = None
depends_on = 'e025de45166e'
Ah, I see .. it's strange indeed to have the same identifier for a depends_on and a down_revision, it should be a mistake on my side I think..
Thank you for your quick reply and explanations
silenius
on 17 May 2021
I can confirm that with:
diff --git a/amnesia/alembic/versions/20210503_32b12866f6a2_permissions.py b/amnesia/alembic/versions/20210503_32b12866f6a2_permissions.py
index 998cd5c..0560e3e 100644
--- a/amnesia/alembic/versions/20210503_32b12866f6a2_permissions.py
+++ b/amnesia/alembic/versions/20210503_32b12866f6a2_permissions.py
@@ -14,7 +14,7 @@ import sqlalchemy as sa
revision = '32b12866f6a2'
down_revision = 'e025de45166e'
branch_labels = None
-depends_on = 'e025de45166e'
+depends_on = None
migration_path = Path(__file__)
migration_sql_path = migration_path.parent.parent / 'sql'
it works with 1.6.2
silenius
on 17 May 2021
Great! Glad that worked, thanks for raising this.
@CaselIT I noticed the bug occurs only when depends_on = 'e025de45166e', and not when depends_on = ('e025de45166e',). Should this give a warning or error here or just handle it transparently (as previous versions evidently did)?
simonbowly
on 17 May 2021
Thanks for looking into it @simonbowly
I'm not actually sure if both versions are allowed. cc @zzzeek
CaselIT
on 17 May 2021
I would say let's warn, so that things dont break but people are encouraged to repair it. thanks for looking into it!
zzzeek
on 17 May 2021
@simonbowly did you want me to look at this or do you have something you're planning?
zzzeek
on 20 May 2021
I wanted to ask the same thing.
Also, I was thinking that I'm not sure we should warn for this if it's a string. I mean down_revision behalves the same, it can be None, a string or a tuple of strings
CaselIT
on 20 May 2021
it's my bug anyway, it's in the topological sort algo.
zzzeek
on 20 May 2021
Mike Bayer has proposed a fix for this issue in the master branch:
ensure heads remain unique in topological https://gerrit.sqlalchemy.org/c/sqlalchemy/alembic/+/2835
sqla-tester
on 20 May 2021
Nice one, thanks - I was having trouble reproducing this in tests. There's a related issue when downgrading in this case of duplicated dependencies, I hit this assertion when trying to downgrade the revision in question:
Simplest approach I think is to make sure _all_down_revisions and _normalised_down_revisions are de-duped.
simonbowly
on 20 May 2021
Created a changeset for this but I guess gerrit doesn't link if the issue is closed - can open a separate issue if this needs a more complete description?
simonbowly
on 20 May 2021
Simon Bowly has proposed a fix for this issue in the master branch:
De-duplicate Revision.down_revision helpers. https://gerrit.sqlalchemy.org/c/sqlalchemy/alembic/+/2836
sqla-tester
on 20 May 2021
Related issues
Ahtii
路
8Comments
sqlalchemy-bot
路
8Comments
sqlalchemy-bot
路
9Comments
a372661369
路
10Comments
am17torres
路
7Comments