5

我目前的 Python 脚本存在问题，当我从 cursor.execute() 为特定函数执行 SQL 函数时，它运行该函数，函数完成，然后脚本挂起近五个小时，然后恢复其余部分的程序。

我在 pgAdminIII 中观察我的函数的服务器状态，因为它是从 Python 调用的，当函数完成时，服务器只显示与我的 python 用户的打开连接。之前它会在事务中空闲，但在添加 conn.set_isolation_level(0) 之后，它只显示打开的连接。

我还在 cursor.execute() 周围放置了打印，但需要五个小时才能继续执行以下打印语句。我尝试终止连接并重新启动它无济于事。我完全从我的脚本中剥离了函数调用，所以它是我的脚本处理的唯一过程。没有任何效果。

困难在于双方都一直指向对方是问题的根源。我假设这是这个特定功能的某种交互效果。运行特定功能后，也许没有从 postgres 将信号发送回 python？其他功能都没有与相同的执行方法有关的问题。

想法？解决方案？-我正在考虑超时，但运行时间可以从 20 分钟到 2 小时不等。- 它运行的函数创建一个表并仅返回一个说明“完成”的字符串，所有操作在它作为服务器状态下的活动函数消失后都在数据库中进行说明。

这是我用于复制问题的代码，与我的主脚本隔离：

#!/usr/bin/env python

import sys
import os
import smtplib
import ftplib
import gzip
import logging
import shutil
import argparse
import traceback
import subprocess
from email.mime.text import MIMEText

import psycopg2
import psycopg2.extras
import psycopg2.extensions
from psycopg2 import OperationalError

pg_db    = "ppl"
pg_port  = "5432"
pg_user  = "<user>"
pg_pass  = "<pass>"
pg_host  = "<host>"

# connect to database
try:
    conn = psycopg2.connect(database=pg_db,
                            port=pg_port, 
                            user=pg_user, 
                            password=pg_pass, 
                            host=pg_host)
    conn.set_isolation_level(0)
except:
    print "Unable to connect to the database."

cur = conn.cursor()

print 'Starting select <function1>'
cur.execute("select <function1>(999999, null );")
print 'Assign variable...'
a = cur.fetchall()
print 'Done'

print 'Starting select <function2>'
cur.execute("select <function2>(999999, null );")
print 'Assign variable...'
b = cur.fetchall()
print 'Done'

print a
print b

conn.close()
sys.exit()

然后我按照这些结果的建议运行了一个 strace：

<previous function statements for about 4k lines>

write(1, "Starting select <function>"..., 45) = 45
sendto(3, "Q\0\0\0009select <function>"..., 58, MSG_NOSIGNAL, NULL, 0) = 58
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "T\0\0\0001\0\1<function_name>\0"..., 16384, 0, NULL, NULL) = 500
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\0mSINFO\0C00000\0Mv_eval_table "..., 16384, 0, NULL, NULL) = 110
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\4\247SINFO\0C00000\0Mcmd := CREATE"..., 16384, 0, NULL, NULL) = 1192
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\23hSINFO\0C00000\0Mcmd := \t--For"..., 16384, 0, NULL, NULL) = 4969
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\0SSINFO\0C00000\0Mlicense_row_i"..., 16384, 0, NULL, NULL) = 84
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\0SSINFO\0C00000\0Mlicense_row_i"..., 16384, 0, NULL, NULL) = 672
...
brk(0xbe9000)                           = 0xbe9000
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\0SSINFO\0C00000\0Mlicense_row_i"..., 16384, 0, NULL, NULL) = 84
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\0SSINFO\0C00000\0Mlicense_row_i"..., 16384, 0, NULL, NULL) = 168
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\0SSINFO\0C00000\0Mlicense_row_i"..., 16384, 0, NULL, NULL) = 1008
...

<does this for about 600k more lines before executing the rest of the script, I am assuming it is indefinitely looping until a timeout>

接下来，我为一个函数运行了一个 cProfile，该函数包装了调用第二个函数的第二个代码块：

Tue Jan 15 16:04:50 2013    function2_prof

         7 function calls in 15755.988 CPU seconds

   Random listing order was used

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 {method 'cursor' of 'psycopg2._psycopg.connection' objects}
        1    0.000    0.000 15755.988 15755.988 test_sql_sub2.py:48(LR2)
        1 15755.988 15755.988 15755.988 15755.988 {method 'execute' of 'psycopg2._psycopg.cursor' objects}
        1    0.000    0.000 15755.988 15755.988 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {method 'close' of 'psycopg2._psycopg.cursor' objects}
        1    0.000    0.000    0.000    0.000 {method 'fetchall' of 'psycopg2._psycopg.cursor' objects}
4

2 回答 2

1

我认为您的功能比您意识到的要多。看看你的 strace：

brk(0xbe9000)                           = 0xbe9000
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\0SSINFO\0C00000\0Mlicense_row_i"..., 16384, 0, NULL, NULL) = 84
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\0SSINFO\0C00000\0Mlicense_row_i"..., 16384, 0, NULL, NULL) = 168
poll([{fd=3, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "N\0\0\0SSINFO\0C00000\0Mlicense_row_i"..., 16384, 0, NULL, NULL) = 1008

brk意思是“给我更多的内存”，所以很明显 Python 正在积累数据。 poll检查是否有数据等待；正返回值（此处为1）表示存在。并recvfrom读取该数据并返回读取的字节数。

所以看起来 Postgres 正在向您发送大量数据，以至于需要花费大量时间来接收。我对 Postgres 的有线格式知之甚少，但license_row_i...在每次民意调查中，听起来你肯定会得到大量的行。该函数不再显示为正在执行，因为它不是；工作已经完成，Postgres 现在只是将结果发回。

难怪双方都指责对方。问题在中间。:)

编辑：啊哈，更多信息暗示RAISE INFO。Psycopg2 确实将所有这些通知存储在连接对象上。

它只保留最后 50 个，但如果您向客户端发送超过 50 万条通知，则需要一段时间才能继续将它们转换为 Python 字符串，丢弃最旧的，附加最新的等等。如果命令-line 客户端完全忽略它们（甚至只是在 C 中完成这一切），它自然会快得多。

所以简单的解决方案是“不要那样做”。:) 您也可以将 Postgres 配置为不将这些发送到客户端，但当然它们最终对调试毫无用处。我可以看到，没有办法要求 psycopg2 不收集发送给客户的通知。

于 2013-01-16T01:26:12.837 回答
1

问题是由于 SQL 函数中的多个 for 循环中的一行：

raise info 'license_row_id := %', rec.license_row_id;

这些引发信息消息在某种程度上没有被 python 适当地处理，因为它们被 bash 和 pgAdmin 处理。我的猜测是，因为它们没有被处理，所以它们不断循环和处理并要求更多内存，直到它无法处理，最后在没有警告或错误的情况下丢弃引发信息并恢复程序。

我注释掉了这个不必要的 raise 信息行，整个脚本在 20 分钟内运行，这是程序的正常运行时间。如果有人知道如何让 python 处理来自 postgresql 的引发信息消息，这可能会进一步回答这个问题。

于 2013-01-16T21:04:06.743 回答