如何获取psycopg2中copy_from()函数的真实执行时间？

你的问题核心在于自定义的日志Cursor没有覆盖copy_from方法，导致这个耗时极长的操作没被纳入时间统计；另外你看到的2000ms和实际20分钟的矛盾，大概率是因为全局时间统计被其他操作干扰，或是print输出缓冲让你误以为程序提前结束。

下面是两种可行的解决方案：

方案1：扩展LoggingCursor，覆盖copy_from方法 #

既然你已经在用自定义LoggingCursor统计SQL操作耗时，只需要给它加上copy_from的重写，和execute/callproc一样加入时间戳逻辑：

class MyLoggingCursor(LoggingCursor):
    def execute(self, query, vars=None):
        self.timestamp = time.time()
        return super(MyLoggingCursor, self).execute(query, vars)
    def callproc(self, procname, vars=None):
        self.timestamp = time.time()
        return super(MyLoggingCursor, self).callproc(procname, vars)
    # 新增：覆盖copy_from方法，加入时间戳记录
    def copy_from(self, file, table, sep='\t', null='\\N', columns=None, size=8192):
        self.timestamp = time.time()
        result = super(MyLoggingCursor, self).copy_from(file, table, sep, null, columns, size)
        # 手动生成日志，记录copy_from的耗时
        logger.debug(f"COPY FROM {table} completed in {(time.time() - self.timestamp)*1000:.2f} ms")
        return result

这样你的日志系统就能准确捕获copy_from的真实耗时，全局时间统计也会包含这个操作的完整耗时，不会再出现和实际等待时间不符的情况。

方案2：直接在copy_from前后单独计时 #

如果不需要把copy_from的耗时纳入统一日志系统，最简单的方式就是在调用前后直接记录时间：

start_time=time.time()
conn = psycopg2.connect(connection_factory=MyLoggingConnection, **db_settings)
conn.initialize(logger)
cur = conn.cursor('cursor_unique_name', cursor_factory=psycopg2.extras.DictCursor)
f = open(target_txt, 'r')

# 单独记录copy_from的开始时间
copy_start = time.time()
cur.copy_from(f, table_name, sep=',')
copy_end = time.time()
print(f"copy_from真实耗时：{(copy_end - copy_start)*1000:.2f} ms", flush=True)

conn.commit()
conn.close()
f.close()
print("总耗时：{}ms".format((time.time()-start_time)*1000), flush=True)

这种方式最直接，能清晰区分copy_from本身的耗时和其他操作（连接、commit、文件IO等）的耗时，适合快速排查问题。

额外说明 #

你提到的“程序打印2000ms但实际等待20分钟”，大概率是因为print的输出被缓冲了——Python标准输出默认是行缓冲，终端运行时可能直到程序完全结束才会打印结果，导致你误以为程序很快结束，但实际一直在执行copy_from。加上flush=True就能强制实时输出，避免误解。

内容的提问来源于stack exchange，提问作者sulv