Go Web应用程序+ MySql驱动程序延迟/超时

Question

更新:在进一步诊断之后，go驱动程序/mysql i驱动程序包出现了问题。事实证明，底层tcp似乎无法检测到损坏的tcp连接。详细信息见go-sql-driver/mysql项目中的github问题：

https://github.com/go-sql-driver/mysql/issues/257

--

目前，我正在经历一个停滞或损坏的网络应用程序后，一段时间的闲置15至48分钟。最关键的问题如下：

• 访问一个URL，站点上的任何url，并完全加载页面(就像页面实际加载的那样，日志显示一个完整的页面已经加载)。
• 关闭浏览器，然后等待。

典型的请求记录如下：

2014/07/13 15:29:54 INFO template rendering: index
2014/07/13 15:29:54 METRIC, URL: /, HANDLER TIME: 7.2339ms, CTX TIME: 5.0894ms, TOTAL TIME: 12.3258ms

经过很长一段时间(从15米到48米)，系统突然记录了下面的这些线路，没有任何交互--这个web应用程序一直闲置着：

[MySQL] 2014/07/13 16:00:09 packets.go:32: read tcp remote-mysql-server-address:3306: connection timed out
[MySQL] 2014/07/13 16:00:09 packets.go:118: write tcp remote-mysql-server-address:3306: broken pipe
2014/07/13 16:00:10 INFO template rendering: index
2014/07/13 16:00:10 METRIC, URL: /, HANDLER TIME: 8.8574ms, CTX TIME: 31m19.2606723s, TOTAL TIME: 31m19.2695329s

注意到“总时间”是31分19秒？另外，注意到同时记录的MySql驱动程序错误吗？

没有任何活动/没有提出任何网络请求。这款网络应用程序简直是无所事事。

最关键的问题是在这些日志消息之后接下来会发生什么：下一个web请求完全停止，永远不会返回响应。

user@govm1:~$ wget http://localhost
--2014-07-13 17:11:18--  http://localhost/
Resolving localhost (localhost)... 127.0.0.1
Connecting to localhost (localhost)|127.0.0.1|:80... connected.
HTTP request sent, awaiting response... Read error (Connection timed out) in headers.
Retrying.

--2014-07-13 17:26:19--  (try: 2)  http://localhost/
Connecting to localhost (localhost)|127.0.0.1|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/html]
Saving to: `index.html.4'

    [ <=>                                                                                  ] 6,310       --.-K/s   in 0.001s

2014-07-13 17:26:20 (9.61 MB/s) - `index.html.4' saved [6310]

它闲置着，没有响应，持续了15分钟，直到wget超时。

现在，如果我提出第二个或第三个请求后，立即被搁置和任何时候，它是停滞的，去网络应用程序响应并返回一个完整的页面为其他请求。没有问题。然后，循环从我提出的最后一个请求开始，让它在站点空闲。

在这15m之后，您可以准确地猜出接下来记录的是什么：

[MySQL] 2014/07/13 17:26:57 packets.go:32: read tcp remote-mysql-server-address:3306: connection timed out
[MySQL] 2014/07/13 17:26:57 packets.go:118: write tcp remote-mysql-server-address:3306: broken pipe
2014/07/13 17:26:57 INFO template rendering: index
2014/07/13 17:26:57 METRIC, URL: /, HANDLER TIME: 6.8938ms, CTX TIME: 15m39.1718434s, TOTAL TIME: 15m39.1787398s

再等15米。

我消除了Windows，集群VIP和运行go web应用程序的防火墙/Linux作为一个问题，因为我在同一个机器上本地运行wget http://localhost，而我得到的这个“停滞”请求永远不会完成，也不会发回任何东西。

--

有很多因素在我的网络应用程序，所以我将尝试概述他们相应。

使用：

• 去1.3
• go-sql-驱动程序/mysql ##版本1.2 (2014-06-03)
• Ubuntu 12.04 LTS，~2014年6月更新
• 窗口天青

请注意，运行MySql的Linux盒是一个运行GoLang应用程序集群的不同的Linux盒，它们位于单独的专用云服务中。MySql vm是一个单独的VM，没有cluserting。

以下是一些相关代码：

// global handler for our DB
var db *sql.DB

// CLI parameter
var dbdsn string

func init() {

    flag.StringVar(&dbdsn, "dbdsn", "root:root@tcp(localhost:3306)/prod?timeout=5s&tls=false&autocommit=true", "Specifies the MySql DSN connection.")
    flag.Parse()

    var err error
    db, err = sql.Open("mysql", dbdsn)
    if err != nil {
        log.Printf("ERROR in sql.Open(): %v", err)
    }

    //db.SetMaxIdleConns(5)

    // verify the DSN is setup properly1
    err = db.Ping()
    if err != nil {
        panic("PANIC when pinging db: " + err.Error()) // proper error handling instead of panic in your app
    }
}

// **********
// * omitted is the Gorilla MUX router and http handler registrations
// **********

func ArticleHandler(w http.ResponseWriter, r *http.Request, c *Context) (err error) {

    m := NewArticle(c)
    id := c.Vars["id"]

    var pid int
    var title, body, excerpt, date, slug, fi, fv, region, region_slug string
    err = db.QueryRow(
        "SELECT p.ID, p.post_title, p.post_content, p.post_excerpt, p.post_date, p.post_name, "+
            "(SELECT fpim.meta_value FROM wp_postmeta fpim WHERE fpim.meta_key = '_wp_attached_file' AND fpim.post_id = (SELECT fpim2.meta_value FROM wp_postmeta fpim2 WHERE fpim2.post_id = p.ID AND fpim2.meta_key = '_thumbnail_id' LIMIT 1) LIMIT 1) AS featured_image, "+
            "(SELECT fpim3.meta_value FROM wp_postmeta fpim3 WHERE fpim3.meta_key = 'fv_video' AND fpim3.post_id = p.ID LIMIT 1) AS featured_video, "+
            "t.name as region, t.slug as region_slug "+
            "FROM wp_posts p "+
            "JOIN wp_term_relationships tr ON tr.object_id=p.ID "+
            "JOIN wp_term_taxonomy tt ON tt.term_taxonomy_id=tr.term_taxonomy_id "+
            "JOIN wp_terms t ON t.term_id=tt.term_id "+
            "WHERE p.post_name=? AND p.post_type='post' AND p.post_status='publish' AND p.post_date <= UTC_TIMESTAMP()"+
            "AND tr.object_id=p.ID AND tt.parent = (SELECT t3.term_id FROM wp_terms t3 WHERE t3.name=? LIMIT 1) LIMIT 1",
        id, RegionsParentCategory).
        Scan(&pid, &title, &body, &excerpt, &date, &slug, &fi, &fv, &region, &region_slug)

    if err != nil {
        if err == sql.ErrNoRows {

            // snipped code for redirects

            // article was not found
            return handleNotFound(w, r, c)

        } else {
            log.Printf("ERROR in .Scan(): %v", err)
        }
    } else {
        m.Region = Region{
            Name: region,
            Slug: region_slug,
        }
        m.Id = pid
        m.Title = title
        m.Body = template.HTML(body) // render the raw html
        m.Excerpt = excerpt
        m.Datetime = date
        m.Slug = slug
        m.FeaturedImageUrl = fi
        m.FeaturedVideoUrl = fv
    }

    web.RenderTemplate(w, "article", m)
    return
}

每次请求多查询5个数据库

除了这个查询之外，您可以看到我的“上下文”被传递到处理程序中，它会运行4到6个额外的SQL查询。因此，每个加载的“文章”处理程序都会使用上面看到的完全相同的模式和*db全局变量来运行大约5-7个SQL查询。

超时/错误总是出现在同一个DB查询上。

下面是一个比较的“上下文”查询：

rows2, err := db.Query(
    "SELECT p.post_title, p.post_name "+
        "FROM wp_posts p "+
        "WHERE p.post_type='page' AND p.post_status='publish' AND p.post_date <= UTC_TIMESTAMP() "+
        "AND p.post_parent = (SELECT p2.ID FROM wp_posts p2 WHERE p2.post_name=? LIMIT 1) "+
        "ORDER BY p.menu_order",
    FooterPagesParentNameSlug)
if err != nil {
    log.Printf("ERROR in AllPages .Query() : %v", err)
} else {
    defer rows2.Close()
    c.AllFooterPages = make([]FooterPage, 0)
    for rows2.Next() {
        var name, slug string
        err := rows2.Scan(&name, &slug)
        if err != nil {
            log.Printf("ERROR in AllPages row.Scan() : %v", err)
        } else {
            p := FooterPage{
                Page: Page{
                    Title: name,
                    Slug:  slug,
                },
            }
            c.AllFooterPages = append(c.AllFooterPages, p)
        }
    }
}

那里没什么特别的。

只有在没有错误的情况下，我才会调用defer rows2.Close()。也许这就是问题的一部分？这个特定的SQL查询似乎记录了负载测试下的错误，比如no response或mysql驱动程序超时。

问题

为什么请求超时记录超过15到30分钟，从空闲的站点？这似乎是我正在使用的mysql驱动程序中的一个bug，可能是打开了一个连接。但是，最后一个http请求是成功的，并返回了一个完整的页面+模板。

我甚至在连接字符串中设置了超时，即5秒。即使mysql服务器有问题，为什么记录15分钟超时/请求？这一要求从何而来？

它仍然可能是MySql驱动程序的问题，阻止了请求的完成--可能是被MySql专用的VM阻塞了，还有一个问题。如果是这样的话，为什么什么都不记录呢？15米到49米的随机超时时间是多少？它通常只有1500万或3100万，但有时有4800万被记录。

在超时值(@15m、31m和48m)中的"15m“倍数非常有趣，在几秒钟内分配了一些填充。

提前谢谢。

Answer 1

千万不要defer db.Close()在里面。init在main执行之前结束，因此永远无法访问打开的连接池。不过，您可以在您的defer db.Close()中调用main。

这也可能是准备好的语句的问题，它们属于连接池，在调用db.Close()时无效。

关于超时，这是一个驱动端超时(从这个问题得到的)。

见我在https://github.com/go-sql-driver/mysql/issues/257上的评论

Answer 2

我应该对每个web请求/处理程序“打开”并推迟db.Close()吗？

不是的。要么创建一个全局的，而不必担心关闭它(就像现在一样)，要么通过一个应用程序上下文传递池(*sql.DB)，即按照https://medium.com/@benbjohnson/structuring-applications-in-go-3b04be4ff091的方式，让您的处理程序在嵌入*sql.DB和其他您可能需要的任何其他上下文类型上作为方法。

您还可以考虑使用http://jmoiron.github.io/sqlx/来帮助将数据库结果编组到structs/ may中，而不必自己跳。

顺便提一句(我敢打赌，这将有助于调试问题)，我会修复第二个代码示例，使其与下面的代码匹配--因为当您遇到错误时，您只是在记录错误，但是您的代码在返回时会继续进行：

rows2, err := db.Query(`
    SELECT p.post_title, p.post_name
    FROM wp_posts p 
    WHERE p.post_type='page' AND p.post_status='publish' AND p.post_date <= UTC_TIMESTAMP()
    AND p.post_parent = (SELECT p2.ID FROM wp_posts p2 WHERE p2.post_name=? LIMIT 1)
    ORDER BY p.menu_order`, FooterPagesParentNameSlug)
if err != nil {
    log.Printf("ERROR in AllPages .Query() : %v", err)
    return err
}
defer rows2.Close()

c.AllFooterPages = make([]FooterPage, 0)

for rows2.Next() {
    var name, slug string
    err := rows2.Scan(&name, &slug)
    if err != nil {
        log.Printf("ERROR in AllPages row.Scan() : %v", err)
        return err // Same here!
    }
// Rest of your code
}