trace.test.cc

Go to the documentation of this file.

/*
 * Copyright (c) 2021 Daniel R. Carvalho
 * All rights reserved
 *
 * Redistribution and use in source and binary forms, with or without
 * modification, are permitted provided that the following conditions are
 * met: redistributions of source code must retain the above copyright
 * notice, this list of conditions and the following disclaimer;
 * redistributions in binary form must reproduce the above copyright
 * notice, this list of conditions and the following disclaimer in the
 * documentation and/or other materials provided with the distribution;
 * neither the name of the copyright holders nor the names of its
 * contributors may be used to endorse or promote products derived from
 * this software without specific prior written permission.
 *
 * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
 * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
 * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
 * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
 * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
 * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
 * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
 * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
 * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
 * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
 * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 */
 
#include <gtest/gtest.h>
 
#include <sstream>
#include <string>
 
#include "base/gtest/cur_tick_fake.hh"
#include "base/gtest/logging.hh"
#include "base/named.hh"
#include "base/trace.hh"
 
using namespace gem5;
 
// In test SetGetLogger this logger will be assigned to be the one returned
// by Tracer::getDebugLogger(). All tests before that test should assume
// that getDebugLogger() returns a cerr-based logger, and all tests after
// that test should assume that this logger is returned
std::stringstream ss;
trace::OstreamLogger main_logger(ss);
 
// Instantiate the mock class to have a valid curTick of 0
GTestTickHandler tickHandler;
 
namespace gem5
{
namespace debug
{
SimpleFlag TraceTestDebugFlag("TraceTestDebugFlag",
    "Exclusive debug flag for the trace tests");
} // namespace debug
} // namespace gem5
 
std::string
getString(std::ostream &os)
{
    auto buf = os.rdbuf();
    std::ostringstream oss;
    oss << buf;
    return oss.str();
}
 
std::string
getString(trace::Logger *logger)
{
    return getString(logger->getOstream());
}
 
TEST(TraceTest, LogSimpleMessage)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    logger.logMessage(Tick(100), "", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Test message");
}
 
TEST(TraceTest, LogMessageName)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
}
 
TEST(TraceTest, LogMessageMaxTick)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    logger.logMessage(MaxTick, "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "Foo: Test message");
}
 
TEST(TraceTest, LogMessageFlagDisabled)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    logger.logMessage(Tick(100), "Foo", "Bar", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
}
 
TEST(TraceTest, LogMessageTickDisabledAndEnableDisable)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
 
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("FmtTicksOff", true));
 
    logger.logMessage(Tick(200), "Foo", "", "Test message");
#if TRACING_ON
    ASSERT_EQ(getString(&logger), "Foo: Test message");
#else
    ASSERT_EQ(getString(&logger), "    200: Foo: Test message");
#endif
 
    debug::changeFlag("FmtTicksOff", false);
    trace::disable();
 
    logger.logMessage(Tick(300), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "    300: Foo: Test message");
}
 
TEST(TraceTest, LogMessageFlagEnabled)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("FmtFlag", true));
 
    logger.logMessage(Tick(100), "Foo", "Bar", "Test message");
#if TRACING_ON
    ASSERT_EQ(getString(&logger), "    100: Bar: Foo: Test message");
#else
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
#endif
 
    debug::changeFlag("FmtFlag", false);
    trace::disable();
}
 
TEST(TraceTest, LogMessageActivateOne)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    ObjectMatch activate_foo("Foo");
    ObjectMatch activate_bar("Bar");
 
    // Activate foo.
    logger.setActivate(activate_foo);
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
    logger.logMessage(Tick(100), "Bar", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
 
    // When setting a new activate, the old activates are not kept.
    logger.setActivate(activate_bar);
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
    logger.logMessage(Tick(100), "Bar", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Bar: Test message");
}
 
TEST(TraceTest, LogMessageActivateMultiple)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    ObjectMatch activate_foo("Foo");
    ObjectMatch activate_bar("Bar");
    ObjectMatch activate_thy("Thy");
 
    // Activate foo and bar
    logger.setActivate(activate_foo);
    logger.addActivate(activate_bar);
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
    logger.logMessage(Tick(100), "Bar", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Bar: Test message");
    logger.logMessage(Tick(100), "Thy", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
 
    // Make sure that when setting a new activate, the old activates
    // are not kept
    logger.setActivate(activate_thy);
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
    logger.logMessage(Tick(100), "Bar", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
    logger.logMessage(Tick(100), "Thy", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Thy: Test message");
}
 
TEST(TraceTest, LogMessageIgnoreOne)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    ObjectMatch ignore_foo("Foo");
    ObjectMatch ignore_bar("Bar");
 
    // Ignore foo
    logger.setIgnore(ignore_foo);
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
    logger.logMessage(Tick(100), "Bar", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Bar: Test message");
 
    // Make sure that when setting a new ignore the old ignores are not kept
    logger.setIgnore(ignore_bar);
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
    logger.logMessage(Tick(100), "Bar", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
}
 
TEST(TraceTest, LogMessageIgnoreMultiple)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    ObjectMatch ignore_foo("Foo");
    ObjectMatch ignore_bar("Bar");
    ObjectMatch ignore_thy("Thy");
 
    // Ignore foo and bar
    logger.setIgnore(ignore_foo);
    logger.addIgnore(ignore_bar);
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
    logger.logMessage(Tick(100), "Bar", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
    logger.logMessage(Tick(100), "Thy", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Thy: Test message");
 
    // Make sure that when setting a new ignore, the old sub-ignores
    // are not kept
    logger.setIgnore(ignore_thy);
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
    logger.logMessage(Tick(100), "Bar", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Bar: Test message");
    logger.logMessage(Tick(100), "Thy", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
}
 
TEST(TraceTest, LogMessageActivateAndIgnore)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    ObjectMatch foo("Foo");
    ObjectMatch bar("Bar");
 
    // Activate foo and ignore bar
    logger.setActivate(foo);
    logger.setIgnore(bar);
    logger.logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
    logger.logMessage(Tick(100), "Bar", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
    logger.logMessage(Tick(100), "Thy", "", "Test message");
    // When the Activate list is not empty and thy is not in the list,
    // log of Thy will not be displayed.
    ASSERT_EQ(getString(&logger), "");
}
 
TEST(TraceTest, DumpIgnored)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    ObjectMatch ignore_foo("Foo");
    logger.setIgnore(ignore_foo);
    std::string message = "Test message";
    logger.dump(Tick(100), "Foo", message.c_str(), message.size(), "");
    ASSERT_EQ(getString(&logger), "");
}
 
TEST(TraceTest, DumpSimple)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("FmtFlag", true));
    std::string message = "Test message";
    logger.dump(Tick(100), "Foo", message.c_str(), message.size(), "Bar");
#if TRACING_ON
    ASSERT_EQ(getString(&logger),
        // logMessage prefix
        "    100: Bar: Foo: "
        // Byte number + 2 spaces
        "00000000  "
        // 8 bytes + 1 space + 4 bytes + ((16 - 12) * 3) spaces
        "54 65 73 74 20 6d 65 73  73 61 67 65              "
        // 1 space + 12 chars + \n
        " Test message\n");
#else
    ASSERT_EQ(getString(&logger),
        // logMessage prefix
        "    100: Foo: "
        // Byte number + 2 spaces
        "00000000  "
        // 8 bytes + 1 space + 4 bytes + ((16 - 12) * 3) spaces
        "54 65 73 74 20 6d 65 73  73 61 67 65              "
        // 1 space + 12 chars + \n
        " Test message\n");
#endif
    debug::changeFlag("FmtFlag", false);
    trace::disable();
}
 
TEST(TraceTest, DumpMultiLine)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    std::string message =
        "This is a very long line that will span over multiple lines";
    logger.dump(Tick(100), "Foo", message.c_str(), message.size(), "");
    ASSERT_EQ(getString(&logger),
        "    100: Foo: 00000000  "
        "54 68 69 73 20 69 73 20  61 20 76 65 72 79 20 6c   This is a very l\n"
        "    100: Foo: 00000010  "
        "6f 6e 67 20 6c 69 6e 65  20 74 68 61 74 20 77 69   ong line that wi\n"
        "    100: Foo: 00000020  "
        "6c 6c 20 73 70 61 6e 20  6f 76 65 72 20 6d 75 6c   ll span over mul\n"
        "    100: Foo: 00000030  "
        "74 69 70 6c 65 20 6c 69  6e 65 73                  tiple lines\n");
}
 
TEST(TraceTest, DISABLED_GetNullLogger)
{
    trace::Logger *logger = trace::getDebugLogger();
    ASSERT_FALSE(logger == nullptr);
 
    gtestLogOutput.str("");
    logger->logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(gtestLogOutput.str(), "    100: Foo: Test message");
}
 
TEST(TraceTest, SetGetLogger)
{
    // NOTE: From now on getDebugLogger will use main_logger to avoid
    // having to check cerr. This assumes that tests are run in the order
    // they appear from line 1 to the last line of this file.
    trace::setDebugLogger(&main_logger);
 
    // Set message with local variable, and retrieve the string with
    // the debug-logger getter
    main_logger.logMessage(Tick(100), "Foo", "", "Test message");
    auto logger_from_getter = trace::getDebugLogger();
    ASSERT_EQ(getString(logger_from_getter), "    100: Foo: Test message");
}
 
TEST(TraceTest, Output)
{
    trace::getDebugLogger()->logMessage(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(trace::output()), "    100: Foo: Test message");
}
 
TEST(TraceTest, DprintfFlagIgnore)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    ObjectMatch ignore_foo("Foo");
    logger.setIgnore(ignore_foo);
    logger.dprintf_flag(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "");
}
 
TEST(TraceTest, DprintfFlagZeroArgs)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    logger.dprintf_flag(Tick(100), "Foo", "", "Test message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
}
 
TEST(TraceTest, DprintfFlagOneArg)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    logger.dprintf_flag(Tick(100), "Foo", "", "Test %s", "message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
}
 
TEST(TraceTest, DprintfFlagMultipleArgs)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    logger.dprintf_flag(Tick(100), "Foo", "", "Test %s %c %d %x",
        "message", 'A', 217, 0x30);
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message A 217 30");
}
 
TEST(TraceTest, DprintfFlagEnabled)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("FmtFlag", true));
    logger.dprintf_flag(Tick(100), "Foo", "Bar", "Test %s", "message");
#if TRACING_ON
    ASSERT_EQ(getString(&logger), "    100: Bar: Foo: Test message");
#else
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
#endif
    debug::changeFlag("FmtFlag", false);
    trace::disable();
}
 
TEST(TraceTest, DprintfIgnore)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    ObjectMatch ignore_foo("Foo");
    logger.setIgnore(ignore_foo);
    logger.dprintf(Tick(100), "Foo", "Test message");
    ASSERT_EQ(getString(&logger), "");
}
 
TEST(TraceTest, DprintfEnabled)
{
    std::stringstream ss;
    trace::OstreamLogger logger(ss);
 
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("FmtFlag", true));
    logger.dprintf(Tick(100), "Foo", "Test %s", "message");
    ASSERT_EQ(getString(&logger), "    100: Foo: Test message");
    debug::changeFlag("FmtFlag", false);
    trace::disable();
}
 
TEST(TraceTest, DprintfWrapper)
{
    std::stringstream ss, ss_flag;
    trace::OstreamLogger logger(ss);
    trace::OstreamLogger logger_flag(ss_flag);
 
    logger.dprintf(Tick(100), "Foo", "Test %s %c %d %x",
        "message", 'A', 217, 0x30);
    logger_flag.dprintf_flag(Tick(100), "Foo", "", "Test %s %c %d %x",
        "message", 'A', 217, 0x30);
    ASSERT_EQ(getString(&logger), getString(&logger_flag));
}
 
TEST(TraceTest, MacroDDUMP)
{
    StringWrap name("Foo");
    std::string message = "Test message";
 
    // Flag enabled
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true));
    EXPECT_TRUE(debug::changeFlag("FmtFlag", true));
    DDUMP(TraceTestDebugFlag, message.c_str(), message.size());
#if TRACING_ON
    ASSERT_EQ(getString(trace::output()),
        "      0: TraceTestDebugFlag: Foo: 00000000  "
        "54 65 73 74 20 6d 65 73  73 61 67 65               Test message\n");
#else
    ASSERT_EQ(getString(trace::output()), "");
#endif
 
    // Flag disabled
    trace::disable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false));
    DDUMP(TraceTestDebugFlag, message.c_str(), message.size());
    ASSERT_EQ(getString(trace::output()), "");
}
 
TEST(TraceTest, MacroDPRINTF)
{
    StringWrap name("Foo");
 
    // Flag enabled
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true));
    EXPECT_TRUE(debug::changeFlag("FmtFlag", true));
    DPRINTF(TraceTestDebugFlag, "Test message");
#if TRACING_ON
    ASSERT_EQ(getString(trace::output()),
        "      0: TraceTestDebugFlag: Foo: Test message");
#else
    ASSERT_EQ(getString(trace::output()), "");
#endif
 
    // Flag disabled
    trace::disable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false));
    DPRINTF(TraceTestDebugFlag, "Test message");
    ASSERT_EQ(getString(trace::output()), "");
}
 
TEST(TraceTest, MacroDPRINTFS)
{
    Named named("Foo");
#if TRACING_ON
    Named *named_ptr = &named;
#endif
 
    // Flag enabled
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true));
    EXPECT_TRUE(debug::changeFlag("FmtFlag", true));
#if TRACING_ON
    DPRINTFS(TraceTestDebugFlag, named_ptr, "Test message");
    ASSERT_EQ(getString(trace::output()),
        "      0: TraceTestDebugFlag: Foo: Test message");
#endif
 
    // Flag disabled
    trace::disable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false));
#if TRACING_ON
    DPRINTFS(TraceTestDebugFlag, named_ptr, "Test message");
    ASSERT_EQ(getString(trace::output()), "");
#endif
}
 
TEST(TraceTest, MacroDPRINTFR)
{
    // Flag enabled
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true));
    EXPECT_TRUE(debug::changeFlag("FmtFlag", true));
    DPRINTFR(TraceTestDebugFlag, "Test message");
#if TRACING_ON
    ASSERT_EQ(getString(trace::output()), "TraceTestDebugFlag: Test message");
#else
    ASSERT_EQ(getString(trace::output()), "");
#endif
 
    // Flag disabled
    trace::disable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false));
    DPRINTFR(TraceTestDebugFlag, "Test message");
    ASSERT_EQ(getString(trace::output()), "");
}
 
TEST(TraceTest, MacroDPRINTFN)
{
    StringWrap name("Foo");
    DPRINTFN("Test message");
#if TRACING_ON
    ASSERT_EQ(getString(trace::output()), "      0: Foo: Test message");
#else
    ASSERT_EQ(getString(trace::output()), "");
#endif
}
 
TEST(TraceTest, MacroDPRINTFNR)
{
    DPRINTFNR("Test message");
#if TRACING_ON
    ASSERT_EQ(getString(trace::output()), "Test message");
#else
    ASSERT_EQ(getString(trace::output()), "");
#endif
}
 
TEST(TraceTest, MacroDPRINTF_UNCONDITIONAL)
{
    StringWrap name("Foo");
 
    // Flag enabled
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true));
    EXPECT_TRUE(debug::changeFlag("FmtFlag", true));
    DPRINTF_UNCONDITIONAL(TraceTestDebugFlag, "Test message");
#if TRACING_ON
    ASSERT_EQ(getString(trace::output()),
        "      0: TraceTestDebugFlag: Foo: Test message");
#else
    ASSERT_EQ(getString(trace::output()), "");
#endif
 
    // Flag disabled
    trace::disable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false));
    DPRINTF_UNCONDITIONAL(TraceTestDebugFlag, "Test message");
#if TRACING_ON
    ASSERT_EQ(getString(trace::output()), "      0: Foo: Test message");
#else
    ASSERT_EQ(getString(trace::output()), "");
#endif
}
 
TEST(TraceTest, GlobalName)
{
    // Flag enabled
    trace::enable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", true));
    EXPECT_TRUE(debug::changeFlag("FmtFlag", true));
    DPRINTF(TraceTestDebugFlag, "Test message");
#if TRACING_ON
    ASSERT_EQ(getString(trace::output()),
        "      0: TraceTestDebugFlag: global: Test message");
#else
    ASSERT_EQ(getString(trace::output()), "");
#endif
 
    // Flag disabled
    trace::disable();
    EXPECT_TRUE(debug::changeFlag("TraceTestDebugFlag", false));
    DPRINTF(TraceTestDebugFlag, "Test message");
    ASSERT_EQ(getString(trace::output()), "");
}