在本文中，你将学习如何使用 profiler 来识别应用程序发送到数据库管理系统的SQL查询。 这个主题是迄今为止我最喜欢的主题之一。 今天，几乎每个应用程序都至少使用一个关系型数据库，而且几乎所有的场景都会不时地遇到由SQL查询引起的延迟。 此外，今天，应用程序使用更复杂的方式来实现持久层；在许多情况下，应用程序发送的SQL查询是由框架或库动态创建的。 这些动态生成的查询很难识别，但 profiler 可以发挥一些作用，大大简化你的调查。

我们将使用一个用 https://gitee.com/tunte/java-troubleshooting-sample.git 项目 da-ch7-ex2 实现的场景来了解一个方法执行了多少次， 并拦截了应用程序在一个关系数据库上运行的SQL查询。 然后我们将证明，即使应用程序与一个框架一起工作，并且不直接处理查询，也可以检索到已执行的SQL查询。 最后，我们将用几个例子进一步讨论这个问题。

使用 profiler 来检索不是由框架生成的SQL查询

这里时使用一个例子来演示如何使用 profiler 来获得一个应用程序执行的SQL查询。 我们将使用一个简单的应用程序，直接将查询发送到 DBMS，而不使用框架。

让我们启动项目 da-ch7-ex2 并使用 Profiler 选项卡，正如你在《Java 故障诊断 - 使用剖析技术识别资源消耗问题》中学到的那样。 项目 da-ch7-ex2 也是一个小应用。 它配置了一个有两个表（product 和 purchase）的内存数据库，并用一些记录来填充这些表。 该应用在调用端点 /products 时公开了所有购买的产品。 我所说的 "购买的产品 "是指在购买表中至少有一条购买记录的产品。 目的是分析应用程序在调用这个端点时的行为，而不用先分析代码。 这样，我们就可以看到仅仅通过使用 profiler 就能得到多少东西。

在图 1 中，我们使用 Profiler 选项卡，因为你已经在《Java 故障诊断 - 使用剖析技术识别资源消耗问题》中学习了采样， 但请记住，在任何现实世界的场景中，你都要从采样开始。 我们启动应用程序，并使用 cURL 或 Postman，调用 /products 端点。 profiler 向我们准确地显示了所发生的情况：

1. 一个属于 PurchaseController 类的方法 findPurchasedProductNames() 被调用。
2. 这个方法委托了对 PurchaseService 类中 getProductNamesForPurchases() 方法的调用。
3. ProductService 中的 getProductNamesForPurchases() 方法调用 PurchaseRepository 中的 findAll()。
4. ProductService 中的 getProductNamesForPurchases() 方法调用了 ProductRepository 中的 findProduct() 10次。

这不是很神奇吗？我们甚至没有研究代码，而我们已经知道了关于这个执行的很多事情。 这些细节是非常棒的，因为现在你清楚地知道应该从哪里进入代码，以及你可以期望找到什么。 profiler 给了你类名、方法名，以及它们如何相互调用。 现在让我们看看清单1中的代码，并找出所有这些发生的地方。 通过使用 profiler，我们可以看到大多数事情都发生在 PurchaseService 类中的 getProductNamesForPurchases() 方法中，所以这很可能是我们需要分析的地方。

清单 1 该算法在 PurchaseService 类中的实现

@Service
public class PurchaseService {

  private final ProductRepository productRepository;
  private final PurchaseRepository purchaseRepository;

  public PurchaseService(ProductRepository productRepository,
                         PurchaseRepository purchaseRepository) {
    this.productRepository = productRepository;
    this.purchaseRepository = purchaseRepository;
  }

  public Set<String> getProductNamesForPurchases() {
    Set<String> productNames = new HashSet<>();
    List<Purchase> purchases = purchaseRepository.findAll(); // 从数据库表中获取所有购买记录

//迭代每个产品
    for (Purchase p : purchases) {
      Product product =
        productRepository.findProduct(p.getProduct()); // 获取有关购买的产品的详细信息
      productNames.add(product.getName());  // 将产品添加到一个集合中
    }

    return productNames; // Returns the set of products
  }
}

观察一下实现的行为：应用程序在一个list中获取一些数据，然后对其进行迭代，从数据库中获取更多数据。 这样的实现通常表明了一个设计问题，因为你通常可以将这么多查询的执行减少到一个。 很明显，执行的查询越少，应用程序的效率就越高。

在这个例子中，直接从代码中检索查询是毫不费力的。 因为 profiler 准确地显示了它们的位置，而且应用程序很小，所以找到这些查询不是问题。 但现实世界的应用程序并不小，而且在许多情况下，直接从代码中检索查询并不容易。 但是不用担心！你可以使用 profiler 来检索查询！你可以使用 profiler 来检索应用程序发送至数据库管理系统的所有SQL查询。 你可以在图 2 中看到这个演示。 你没有选择 CPU 按钮，而是选择 JDBC 按钮来开始对SQL查询进行剖析。

该工具在幕后所做的事情非常简单：一个Java应用通过JDBC驱动将SQL查询发送到DBMS。 profiler 拦截驱动，在驱动将查询发送到DBMS之前复制查询。 图 3 显示了这种方法。 其结果非常好，因为你可以简单地复制和粘贴数据库客户端中的查询，在那里你可以运行它们或调查它们的计划。

profiler 还会显示发送查询的次数。在这种情况下，应用程序发送第一个查询10次。 这种设计是错误的，因为它多次重复相同的查询，因此花费了不必要的时间和资源。 实现代码的开发人员尝试获取 purchases 信息，然后获取每次购买的产品详细信息。 但是，使用两个表(product和purchase)之间的联结直接查询就可以一步解决问题。 幸运的是，使用 VisualVM，你找到了问题的原因，也确切地知道要修改什么来改进这个应用程序。

图 4 告诉你如何找到代码库中发送查询的部分。 你可以展开执行栈，通常可以找到应用程序代码库中的第一个方法。

清单 1 显示了我们用 profiler 确定其调用的代码。 一旦你确定了问题的来源，就应该阅读代码并找到优化实现的方法。 在这个例子中，所有的东西都可以合并成一个查询。 这可能看起来是一个愚蠢的错误，但相信我，你会发现这些类型的案例，甚至在由强大的组织实现的较大的应用程序中。

清单 2 该算法在 ProductService 类中的实现。

@Service
public class PurchaseService {

  // Omitted code

  public Set<String> getProductNamesForPurchases() {
    Set<String> productNames = new HashSet<>();
    List<Purchase> purchases = purchaseRepository.findAll();     // The app gets a list of all products.
    for (Purchase p : purchases) {     // Iterates through each product
      Product product = productRepository.findProduct(p.getProduct());      // Gets the product details
      productNames.add(product.getName());
    }
    return productNames;
  }
}

例子 da-ch7-ex2 使用 JDBC 发送 SQL 查询到 DBMS。 这个应用程序的SQL查询直接存在于Java代码中（清单 3）， 并且是原生形态，所以你可能认为直接从代码中复制查询并不困难。 但在今天的应用程序中，你会在代码中较少遇到原生查询。 现在，许多应用程序使用 Hibernate（最常用的Java Persistence API [JPA]实现） 或 Java Object Oriented Querying（JOOQ）等框架，本地查询不直接在代码中出现。 (你可以在他们的 GitHub 资源库中找到更多关于 JOOQ 的细节：https://github.com/jOOQ/jOOQ）。

清单 3 一个使用原生SQL查询的仓库

@Repository
public class ProductRepository {

  private final JdbcTemplate jdbcTemplate;

  public ProductRepository(JdbcTemplate jdbcTemplate) {
    this.jdbcTemplate = jdbcTemplate;
  }

  public Product findProduct(int id) {
    String sql = "SELECT * FROM product WHERE id = ?"; // A native SQL query the app sends to the DBMS
    return jdbcTemplate.queryForObject(sql, new ProductRowMapper(), id);
  }
}

使用 profiler 来获取框架生成的SQL查询结果

让我们看一下更特别的东西。 为了进一步证明 profiler 在调查SQL查询方面的作用，让我们回顾一下项目 da-ch7-ex3。 从算法的角度来看，这个项目和前一个项目做的事情是一样的：返回购买产品的名称。 我故意保持相同的逻辑，以简化这个例子，使其具有可比性。

接下来的代码片段显示了 Spring Data JPA repository 的定义。 repository 是一个简单的接口，你在任何地方都看不到SQL查询。 使用 Spring Data JPA，应用程序会在幕后根据方法的名称或定义查询的特定方式（称为 Java Persistence Query Language（JPQL））生成查询。 无论哪种方式，都没有从代码中复制和粘贴查询的简单方法。

一些框架在幕后根据你写的代码和配置生成SQL查询。 在这些情况下，要获得已执行的查询就更具有挑战性。 但 profiler 可以帮助你，在它们被发送到DBMS之前从JDBC驱动中提取它们：

public interface ProductRepository
    extends JpaRepository<Product, Integer> {
}

profiler 来了。由于该工具在应用程序将查询发送到DBMS之前就进行了拦截， 我们仍然可以用它来找到应用程序到底使用了哪些查询。 启动应用程序 da-ch7-ex3，使用 VisualVM 对 SQL 查询进行剖析，就像我们对前两个项目所做的那样。

图 5 向你展示了工具在剖析 /products 端点调用时的显示。 该应用程序发送了两个SQL查询。注意到查询中的别名有奇怪的名字，因为查询是框架生成的。 同时注意到，即使服务中的逻辑是相同的，而且应用程序调用了10次 repository 方法， 第二个查询也只执行了一次，因为Hibernate在可能的地方优化了执行。 现在，如果需要，你可以用SQL开发客户端复制和调查这个查询。 在很多情况下，调查一个缓慢的查询需要在SQL客户端中运行它，以观察查询的哪一部分给DBMS带来困难。

尽管该方法被调用了10次，但查询只被执行一次。 持久化框架通常都会做这种小把戏吗？虽然它们很聪明，但有时它们在幕后所做的事情会增加复杂性。 另外，没有正确理解框架的人可能会写出导致问题的代码。 这也是使用 profiler 来检查框架生成的查询并确保应用程序做你期望的事情的另一个原因。

我遇到的需要调查的框架问题主要有以下几个方面：

• 造成延迟的缓慢查询—使用 profiler 检查执行时间，很容易发现。
• 由框架产生的多个不需要的查询 (通常是由开发人员所说的N+1查询问题引起的)—使用 profiler 确定查询的执行次数，很容易发现。
• 糟糕的应用设计产生的冗长的事务提交—使用CPU剖析法很容易发现

当一个框架需要从多张表中获取数据时，它通常知道组成一个查询并在一次调用中获取所有的数据。 然而，如果你不正确使用框架，它可能只用一个初始查询获取部分数据，然后，对于最初检索的每条记录， 运行一个单独的查询。 因此，框架不是只运行一个查询，而是会发送一个初始查询加上N个其他的查询（第一个查询检索的N条记录中的每一条）； 我们称之为N+1查询问题，这通常会因为执行许多查询而不是只有一个查询而产生明显的延迟。

大多数开发者似乎都想用日志或 debugger 来调查这种问题。 但是，根据我的经验，这两者都不是找出问题根源的最佳选择。

在这种情况下使用日志的第一个问题是，要确定哪个查询导致了问题，这很有挑战性。 在现实世界的场景中，应用程序可能会发送几十个查询—其中一些是多次的，而且在大多数情况下， 它们都很长，并使用大量的参数。 有了 profiler，它在一个列表中显示所有的查询及其执行时间和执行次数，你几乎可以立即发现问题。 第二个问题是，即使你确定了导致问题的潜在查询（例如，在监控日志时， 你观察到应用程序需要很长的时间来执行一个给定的查询），也不能简单地采取查询并运行它。 在日志中，你发现参数与查询分离。

你可以通过在 da-ch7-ex3 文件的应用程序属性中添加一些参数， 配置你的应用程序在日志中打印由Hibernate生成的查询：

spring.jpa.show-sql=true
spring.jpa.properties.hibernate.format_sql=true
logging.level.org.hibernate.type.descriptor.sql=trace

请注意，你将不得不使用不同的方式来配置日志，这取决于你使用什么技术来实现应用程序。 在本书提供的例子中，我们使用 Spring Boot 和 Hibernate。下一个列表显示了该应用如何在日志中打印查询。

清单 4 显示Hibernate发送的本地查询的日志

Hibernate:
    Select
        product0_.id as id1_0_0_,
        product0_.name as name2_0_0_
    from
        product product0_
    where
        product0_.id=?

2023-3-16 13:57:26.566 TRACE 9512 --- [nio-8080-exec-2] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [INTEGER] - [1]
2023-3-16 13:57:26.568 TRACE 9512 --- [nio-8080-exec-2] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([name2_0_0_] : [VARCHAR]) - [Chocolate]

日志向我们展示了查询，并给了我们查询的输入和输出。 但如果你想单独运行查询，你需要将参数值与查询绑定。 而且，当多个查询被记录下来时，寻找你所需要的东西可能真的很令人沮丧。 日志也不显示应用程序的哪个部分在运行查询，这可能使你的调查更具挑战性。

使用 profiler 来获得以编程方式生成的SQL查询

为了完整起见，让我们再来研究一个例子，演示当应用程序以编程方式定义查询时，profiler 如何工作。 我们将调查 Hibernate（我们的例子使用的框架）在一个使用条件查询的应用中生成的查询的性能问题：用Hibernate定义应用的持久层的程序化方式。 你从来没有用这种方法写过查询，无论是原生还是JPQL。

正如你在清单 5 中所看到的，该清单展示了用条件查询重新实现的 ProductRepository 类，这种方法更加冗长。 它通常被认为是更难的，而且留下了更多的错误空间。 在项目 da-ch7-ex4 中的实现包含了一个错误，这可能会在现实世界的应用程序中造成严重的性能问题。 让我们看看是否能找到这个问题，并确定 profiler 如何能帮助我们了解错误所在。

清单 5 用 criteria 查询定义的 repository

public class ProductRepository {

  private final EntityManager entityManager;

  public ProductRepository(EntityManager entityManager) {
    this.entityManager = entityManager;
  }

  public Product findById(int id) {
    CriteriaBuilder cb = entityManager.getCriteriaBuilder();
    CriteriaQuery<Product> cq = cb.createQuery(Product.class); // Creating a new query.

    Root<Product> product = cq.from(Product.class); // Specifying the query selects products.
    cq.select(product); // Selecting the products.

    Predicate idPredicate = cb.equal(cq.from(Product.class).get("id"), id); // Defining the condition that becomes part of the WHERE clause on the next line.
    cq.where(idPredicate);  // Defining the where clause

    TypedQuery<Product> query = entityManager.createQuery(cq);
    return query.getSingleResult();  // Running the query and extracting the result.
  }
}

我们使用JDBC分析来拦截应用程序向DBMS发送的查询。 你可以看到，它包含了 product 表和它自己之间的交叉连接（图 6）。 这是一个巨大的问题! 对于我们表中的10条记录，我们没有观察到任何可疑之处。 但是在一个真实世界的应用程序中，表会有更多的记录，这种交叉连接会产生巨大的延迟， 最终甚至是错误的输出（重复的行）。简单地用 VisualVM 拦截查询并读取它，我们就能看到这个问题。

下一个问题是，"为什么应用程序会以这种方式生成查询？" 我喜欢关于JPA实现的说法，比如 Hibernate： "优秀的地方在于它们使查询的生成透明化，并使工作最小化。 不好的是，它们使查询生成透明化，使应用程序更容易出错"。 在使用此类框架时。我一般建议开发者在开发过程中对查询进行剖析，以提前发现此类问题。 使用 profiler 更多是为了审计，而不是发现问题，但这样做是一个很好的安全措施。

在下面的例子中，我故意引入了这个有重大影响的微小错误。我两次调用 from() 方法，指示Hibernate进行交叉连接。

清单 6 交叉连接问题的原因

public class ProductRepository {

  // Omitted code

  public Product findById(int id) {
    CriteriaBuilder cb = entityManager.getCriteriaBuilder();
    CriteriaQuery<Product> cq = cb.createQuery(Product.class);

    Root<Product> product = cq.from(Product.class);  // Calling the CriteriaQuery from() method once
    cq.select(product);

    Predicate idPredicate = cb.equal(cq.from(Product.class).get("id"), id);  // Calling the CriteriaQuery from() method again
    cq.where(idPredicate);

    TypedQuery<Product> query = entityManager.createQuery(cq);
    return query.getSingleResult();
  }
}

解决这个问题很简单：使用 product 实例，而不是第二次调用 CriteriaQuery from() 方法，如下清单所示。

清单 7 Correcting the cross-join issue

public class ProductRepository {

  // Omitted code

  public Product findById(int id) {
    CriteriaBuilder cb = entityManager.getCriteriaBuilder();
    CriteriaQuery<Product> cq = cb.createQuery(Product.class);

    Root<Product> product = cq.from(Product.class);
    cq.select(product);

    Predicate idPredicate = cb.equal(product.get("id"), id);  // Use the already existing Root object
    cq.where(idPredicate);

    TypedQuery<Product> query = entityManager.createQuery(cq);
    return query.getSingleResult();
  }
}

一旦你做了这个小改动，生成的SQL查询将不再包含不需要的交叉连接（图 7）。 但是，该应用程序仍然多次运行同一个查询，这不是最佳的。 应用所运行的算法应该被重构以获得数据，最好只使用一个查询。

语结

profiler 拦截应用程序的执行，并提供关于执行中的代码的基本细节，如每个线程的执行stack跟踪，每个方法的执行时间，以及某个方法被调用了多少次。

在调查延迟问题时，使用profiler的第一步是采样—?一种让profiler拦截执行中的代码而不获得许多细节的方法。 采样对资源的消耗较少，可以观察到执行的全貌。

采样为你提供了三个基本细节：

• 哪些代码在执行—当调查一个问题时，你有时不知道代码的哪一部分在执行，你可以通过采样找到这方面的信息。
• 每个方法的总执行时间—这个细节可以帮助你确定代码的哪一部分会导致潜在的延迟问题。
• CPU的总执行时间—这个细节可以帮助你确定你的代码是在执行时间内 "工作" 还是在等待什么。

有时采样就足以了解问题的来源。但在许多情况下，你需要更多的细节。你可以得到这些细节，对执行进行剖析。

剖析是一个消耗资源的过程。对于一个真实世界的应用程序，几乎总是不可能对整个代码库进行剖析。 出于这个原因，在对细节进行剖析时，你应该过滤你想重点调查的特定包和类。 你通常可以通过先对执行情况进行采样来确定要关注的应用程序的哪一部分。

你通过剖析得到的一个基本细节是一个方法的调用次数。 在采样时，你知道一个方法执行的总时间，但不知道它被调用的频率。 这方面对于识别一个缓慢或错误使用的方法很重要。

你可以使用 profiler 来获取应用程序发送到DBMS的SQL查询。 profiler 拦截任何查询，而不考虑用于实现应用程序持久层的技术。 在调查使用框架（如Hibernate）与数据库合作的应用程序的缓慢查询时，这是非常宝贵的。