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!

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 16 (10 by maintainers)

Commits related to this issue

Most upvoted comments

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

+1
sqla-tester on May 20, 2021

I would say let’s warn, so that things dont break but people are encouraged to repair it. thanks for looking into it!

+1
zzzeek on May 17, 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'
+1
simonbowly on May 17, 2021
Read more comments on GitHub
← Watchy: Failed to connect to ESP32
alembic: change to no longer sort index cols for index sig produces false positives on mysql →