Tôi làm cách nào để cấu hình ứng dụng được hỗ trợ bởi SQLAlchemy?

Question

Có ai có kinh nghiệm lược tả một ứng dụng Python/SQLAlchemy không? Và cách tốt nhất để tìm ra tắc nghẽn và lỗi thiết kế là gì?

Chúng tôi có một ứng dụng Python trong đó lớp cơ sở dữ liệu được xử lý bởi SQLAlchemy. Ứng dụng sử dụng một thiết kế hàng loạt, do đó, rất nhiều yêu cầu cơ sở dữ liệu được thực hiện tuần tự và trong một khoảng thời gian giới hạn. Nó hiện đang mất một chút quá lâu để chạy, do đó, một số tối ưu hóa là cần thiết. Chúng tôi không sử dụng chức năng ORM và cơ sở dữ liệu là PostgreSQL.

Answer 1

Đôi khi chỉ ghi nhật ký SQL đơn giản (được bật thông qua mô-đun ghi nhật ký của python hoặc thông qua đối số echo=True trên create_engine()) có thể cho bạn biết thời gian sử dụng. Ví dụ, nếu bạn đăng nhập một cái gì đó ngay sau khi một hoạt động SQL, bạn sẽ thấy một cái gì đó như thế này trong nhật ký của mình:

17:37:48,325 INFO [sqlalchemy.engine.base.Engine.0x...048c] SELECT ... 
17:37:48,326 INFO [sqlalchemy.engine.base.Engine.0x...048c] {<params>} 
17:37:48,660 DEBUG [myapp.somemessage] 

nếu bạn đăng nhập myapp.somemessage ngay sau khi phẫu thuật, bạn biết điều đó mất 334ms để hoàn thành phần SQL của nhiều thứ.

Ghi nhật ký SQL cũng sẽ minh họa nếu hàng chục/hàng trăm truy vấn đang được phát hành có thể được tổ chức tốt hơn thành ít truy vấn hơn thông qua kết nối. Khi sử dụng tính năng SQLAlchemy ORM, tính năng "háo hức tải" được cung cấp một phần (contains_eager()) hoặc hoàn toàn (eagerload(), eagerload_all()) tự động hóa hoạt động này, nhưng không có ORM nó chỉ có nghĩa là sử dụng kết nối để có thể tải kết quả trên nhiều bảng một kết quả được đặt thay vì nhân số lượng truy vấn khi có thêm chiều sâu (ví dụ: r + r*r2 + r*r2*r3 ...)

Nếu đăng nhập cho thấy các truy vấn riêng lẻ mất quá nhiều thời gian, bạn cần phân tích số lượng thời gian đã sử dụng trong cơ sở dữ liệu xử lý truy vấn, gửi kết quả qua mạng, đang được xử lý bởi DBAPI và cuối cùng được nhận bởi tập hợp kết quả của SQLAlchemy và/hoặc lớp ORM. Mỗi giai đoạn này có thể trình bày các nút cổ chai cá nhân của riêng mình, tùy thuộc vào từng chi tiết cụ thể.

Đối với điều đó bạn cần sử dụng hồ sơ, chẳng hạn như cProfile hoặc hotshot.Dưới đây là một trang trí tôi sử dụng:

import cProfile as profiler 
import gc, pstats, time 

def profile(fn): 
    def wrapper(*args, **kw): 
     elapsed, stat_loader, result = _profile("foo.txt", fn, *args, **kw) 
     stats = stat_loader() 
     stats.sort_stats('cumulative') 
     stats.print_stats() 
     # uncomment this to see who's calling what 
     # stats.print_callers() 
     return result 
    return wrapper 

def _profile(filename, fn, *args, **kw): 
    load_stats = lambda: pstats.Stats(filename) 
    gc.collect() 

    began = time.time() 
    profiler.runctx('result = fn(*args, **kw)', globals(), locals(), 
        filename=filename) 
    ended = time.time() 

    return ended - began, load_stats, locals()['result'] 

Để cấu hình một phần của mã, đặt nó trong một hàm với trang trí:

@profile 
def go(): 
    return Session.query(FooClass).filter(FooClass.somevalue==8).all() 
myfoos = go() 

Sản lượng của hồ sơ có thể được sử dụng để đưa ra một ý tưởng mà thời gian đang được chi tiêu. Ví dụ: nếu bạn thấy tất cả thời gian được sử dụng trong phạm vi cursor.execute(), đó là cuộc gọi DBAPI cấp thấp tới cơ sở dữ liệu và điều đó có nghĩa là truy vấn của bạn phải được tối ưu hóa bằng cách thêm chỉ mục hoặc tái cơ cấu truy vấn và/hoặc lược đồ cơ bản. Đối với nhiệm vụ đó, tôi khuyên bạn nên sử dụng pgadmin cùng với tiện ích EXPLAIN đồ họa của nó để xem loại công việc mà truy vấn đang làm. Nếu bạn thấy hàng nghìn cuộc gọi liên quan đến tìm nạp hàng, điều đó có thể có nghĩa là truy vấn của bạn đang trả về nhiều hàng hơn dự kiến ​​- một sản phẩm Descartes do kết nối không đầy đủ có thể gây ra sự cố này. Tuy nhiên, một vấn đề khác là thời gian trong xử lý kiểu - một loại SQLAlchemy như Unicode sẽ thực hiện mã hóa/giải mã chuỗi trên các tham số ràng buộc và các cột kết quả, có thể không cần thiết trong mọi trường hợp.

Kết quả của tiểu sử có thể hơi khó khăn nhưng sau một số thực hành, chúng rất dễ đọc. Đã từng có ai đó trong danh sách gửi thư tuyên bố chậm và sau khi anh ấy đăng kết quả hồ sơ, tôi có thể chứng minh rằng các vấn đề về tốc độ là do độ trễ của mạng - thời gian sử dụng trong cursor.execute() cũng như tất cả Python các phương thức rất nhanh, trong khi phần lớn thời gian được dành cho socket.receive().

Nếu bạn đang cảm thấy tham vọng, cũng có một ví dụ liên quan hơn về lược tả SQLAlchemy trong các bài kiểm tra đơn vị SQLAlchemy, nếu bạn poke xung quanh http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling. Ở đó, chúng tôi có các thử nghiệm sử dụng các trình trang trí xác nhận số lượng cuộc gọi phương thức tối đa được sử dụng cho các hoạt động cụ thể, do đó nếu một điều gì đó không hiệu quả được kiểm tra, các kiểm tra sẽ tiết lộ nó (điều quan trọng cần lưu ý là trong Python, các cuộc gọi hàm có giá trị cao nhất chi phí của bất kỳ hoạt động nào và số lượng cuộc gọi thường xuyên hơn là không tỷ lệ thuận với thời gian sử dụng). Đáng chú ý là các bài kiểm tra "zoomark" sử dụng lược đồ "bắt giữ SQL" ưa thích để cắt giảm chi phí của DBAPI khỏi phương trình - mặc dù kỹ thuật đó không thực sự cần thiết cho việc lập hồ sơ vườn.

Answer 2

Tôi đã có một số thành công trong việc sử dụng cprofile và xem kết quả trong runnakerun. Điều này ít nhất đã nói với tôi những chức năng và cuộc gọi trong đó mất một thời gian dài và nếu cơ sở dữ liệu là vấn đề. Tài liệu là here. Bạn cần wxpython. Các presentation trên nó là tốt để giúp bạn bắt đầu.
của nó dễ dàng như

import cProfile 
command = """foo.run()""" 
cProfile.runctx(command, globals(), locals(), filename="output.profile") 

Sau đó

python runsnake.py output.profile

Nếu bạn đang tìm kiếm để tối ưu hóa các truy vấn của bạn, bạn sẽ cần postgrsql profiling.

Cũng đáng để đăng nhập để ghi lại các truy vấn, nhưng không có trình phân tích cú pháp nào mà tôi biết để nhận các truy vấn chạy dài (và nó sẽ không hữu ích cho các yêu cầu đồng thời).

sqlhandler = logging.FileHandler("sql.log") 
sqllogger = logging.getLogger('sqlalchemy.engine') 
sqllogger.setLevel(logging.info) 
sqllogger.addHandler(sqlhandler) 

và đảm bảo tuyên bố công cụ tạo của bạn có echo = True.

Khi tôi thực sự thực sự là mã của tôi, đó là vấn đề chính, vì vậy điều cprofile đã giúp.

Answer 3

Có một công thức profiling cực kỳ hữu ích trên SQLAlchemy wiki

Với một vài thay đổi nhỏ,

from sqlalchemy import event 
from sqlalchemy.engine import Engine 
import time 
import logging 

logging.basicConfig() 
logger = logging.getLogger("myapp.sqltime") 
logger.setLevel(logging.DEBUG) 

@event.listens_for(Engine, "before_cursor_execute") 
def before_cursor_execute(conn, cursor, statement, 
         parameters, context, executemany): 
    context._query_start_time = time.time() 
    logger.debug("Start Query:\n%s" % statement) 
    # Modification for StackOverflow answer: 
    # Show parameters, which might be too verbose, depending on usage.. 
    logger.debug("Parameters:\n%r" % (parameters,)) 


@event.listens_for(Engine, "after_cursor_execute") 
def after_cursor_execute(conn, cursor, statement, 
         parameters, context, executemany): 
    total = time.time() - context._query_start_time 
    logger.debug("Query Complete!") 

    # Modification for StackOverflow: times in milliseconds 
    logger.debug("Total Time: %.02fms" % (total*1000)) 

if __name__ == '__main__': 
    from sqlalchemy import * 

    engine = create_engine('sqlite://') 

    m1 = MetaData(engine) 
    t1 = Table("sometable", m1, 
      Column("id", Integer, primary_key=True), 
      Column("data", String(255), nullable=False), 
     ) 

    conn = engine.connect() 
    m1.create_all(conn) 

    conn.execute(
     t1.insert(), 
     [{"data":"entry %d" % x} for x in xrange(100000)] 
    ) 

    conn.execute(
     t1.select().where(t1.c.data.between("entry 25", "entry 7800")).order_by(desc(t1.c.data)) 
    ) 

Output là một cái gì đó như:

DEBUG:myapp.sqltime:Start Query: 
SELECT sometable.id, sometable.data 
FROM sometable 
WHERE sometable.data BETWEEN ? AND ? ORDER BY sometable.data DESC 
DEBUG:myapp.sqltime:Parameters: 
('entry 25', 'entry 7800') 
DEBUG:myapp.sqltime:Query Complete! 
DEBUG:myapp.sqltime:Total Time: 410.46ms 

Sau đó, nếu bạn tìm thấy một kỳ quặc chậm truy vấn, bạn có thể lấy chuỗi truy vấn, định dạng trong các tham số (có thể được thực hiện bằng toán tử định dạng chuỗi %, cho psyco pg2 ít nhất), tiền tố nó với "GIẢI THÍCH ANALYZE" và đẩy đầu ra của kế hoạch truy vấn vào http://explain.depesz.com/ (tìm thấy qua this good article on PostgreSQL performance)