fix: better prompt caching & less debug logging (#323)

Author: ErikBjare

gptme/cli.py

@@ -188,11 +188,10 @@ def main(
     config = get_config()
 
     tool_format = tool_format or config.get_env("TOOL_FORMAT") or "markdown"
-
     set_tool_format(tool_format)
 
     # early init tools to generate system prompt
-    init_tools(tool_allowlist)
+    init_tools(frozenset(tool_allowlist) if tool_allowlist else None)
 
     # get initial system prompt
     initial_msgs = [

gptme/init.py

@@ -30,7 +30,6 @@ def init(model: str | None, interactive: bool, tool_allowlist: list[str] | None)
     _init_done = True
 
     # init
-    logger.debug("Started")
     load_dotenv()
 
     # fixes issues with transformers parallelism
@@ -72,20 +71,21 @@ def init(model: str | None, interactive: bool, tool_allowlist: list[str] | None)
         # for some reason it bugs out shell tests in CI
         register_tabcomplete()
 
-    init_tools(tool_allowlist)
+    init_tools(frozenset(tool_allowlist) if tool_allowlist else None)
 
 
 def init_logging(verbose):
-    # log init
-    handler = RichHandler()
+    handler = RichHandler()  # show_time=False
     logging.basicConfig(
         level=logging.DEBUG if verbose else logging.INFO,
         format="%(message)s",
         datefmt="[%X]",
         handlers=[handler],
     )
+
     # anthropic spams debug logs for every request
     logging.getLogger("anthropic").setLevel(logging.INFO)
+    logging.getLogger("openai").setLevel(logging.INFO)
     # set httpx logging to WARNING
     logging.getLogger("httpx").setLevel(logging.WARNING)
     logging.getLogger("httpcore").setLevel(logging.WARNING)

gptme/llm/__init__.py

@@ -1,6 +1,7 @@
 import logging
 import shutil
 import sys
+import time
 from collections.abc import Iterator
 from functools import lru_cache
 from typing import cast
@@ -95,11 +96,14 @@ def print_clear():
         print(" " * shutil.get_terminal_size().columns, end="\r")
 
     output = ""
+    start_time = time.time()
+    first_token_time = None
     try:
         for char in (
             char for chunk in _stream(messages, model, tools) for char in chunk
         ):
             if not output:  # first character
+                first_token_time = time.time()
                 print_clear()
                 print(f"{PROMPT_ASSISTANT}: ", end="")
             print(char, end="")
@@ -126,6 +130,15 @@ def print_clear():
         return Message("assistant", output + "... ^C Interrupted")
     finally:
         print_clear()
+        if first_token_time:
+            end_time = time.time()
+            logger.debug(
+                f"Generation interrupted after {end_time - start_time:.1f}s "
+                f"(ttft: {first_token_time - start_time:.2f}s, "
+                f"gen: {end_time - first_token_time:.2f}s, "
+                f"tok/s: {len_tokens(output)/(end_time - first_token_time):.1f})"
+            )
+
     return Message("assistant", output)
 
 

gptme/llm/llm_anthropic.py

@@ -349,6 +349,9 @@ def _prepare_messages_for_api(
 
         messages_dicts_new.append({"role": msg["role"], "content": content_parts})
 
+    # set for the first system message (static between sessions)
+    system_messages[0]["cache_control"] = {"type": "ephemeral"}
+
     # set cache points at the two last user messages, as suggested in Anthropic docs:
     # > The conversation history (previous messages) is included in the messages array.
     # > The final turn is marked with cache-control, for continuing in followups.

gptme/logmanager.py

@@ -103,7 +103,7 @@ def __init__(
             # Try to acquire an exclusive lock
             try:
                 fcntl.flock(self._lock_fd, fcntl.LOCK_EX | fcntl.LOCK_NB)
-                logger.debug(f"Acquired lock on {self.logdir}")
+                # logger.debug(f"Acquired lock on {self.logdir}")
             except BlockingIOError:
                 self._lock_fd.close()
                 self._lock_fd = None
@@ -132,7 +132,7 @@ def __del__(self):
             try:
                 fcntl.flock(self._lock_fd, fcntl.LOCK_UN)
                 self._lock_fd.close()
-                logger.debug(f"Released lock on {self.logdir}")
+                # logger.debug(f"Released lock on {self.logdir}")
             except Exception as e:
                 logger.warning(f"Error releasing lock: {e}")
 
@@ -256,7 +256,7 @@ def load(
 
         if not Path(logfile).exists():
             if create:
-                logger.debug(f"Creating new logfile {logfile}")
+                # logger.debug(f"Creating new logfile {logfile}")
                 Path(logfile).parent.mkdir(parents=True, exist_ok=True)
                 Log([]).write_jsonl(logfile)
             else:

gptme/prompts.py

@@ -8,8 +8,8 @@
 import glob
 import logging
 import platform
-import subprocess
 from collections.abc import Generator, Iterable
+from datetime import datetime
 from pathlib import Path
 from typing import Literal
 
@@ -242,8 +242,8 @@ def prompt_systeminfo() -> Generator[Message, None, None]:
 
 def prompt_timeinfo() -> Generator[Message, None, None]:
     """Generate the current time prompt."""
-    # TODO: this should be updated when time changes significantly (such as when resuming a session)
-    prompt = f"## Current Time\n\n**UTC:** {subprocess.run(['date', '-u'], capture_output=True, text=True).stdout.strip()}"
+    # we only set the date in order for prompt caching and such to work
+    prompt = f"## Current Date\n\n**UTC:** {datetime.utcnow().strftime('%Y-%m-%d')}"
     yield Message("system", prompt)
 
 

gptme/tools/__init__.py

@@ -72,7 +72,8 @@
 ]
 
 
-def init_tools(allowlist=None) -> None:
+@lru_cache
+def init_tools(allowlist: frozenset[str] | None = None) -> None:
     """Runs initialization logic for tools."""
     # init python tool last
     tools = list(
@@ -93,22 +94,20 @@ def init_tools(allowlist=None) -> None:
         if tool.name in tools_default_disabled:
             if not allowlist or tool.name not in allowlist:
                 continue
-        load_tool(tool)
+        _load_tool(tool)
 
     for tool_name in allowlist or []:
         if not has_tool(tool_name):
             raise ValueError(f"Tool '{tool_name}' not found")
 
 
-def load_tool(tool: ToolSpec) -> None:
+def _load_tool(tool: ToolSpec) -> None:
     """Loads a tool."""
-    # FIXME: when are tools first initialized?
     if tool in loaded_tools:
         logger.warning(f"Tool '{tool.name}' already loaded")
         return
 
-    if tool.init:
-        tool.init()
+    # tool init happens in init_tools to check that spec is available
     if tool.functions:
         for func in tool.functions:
             register_function(func)

gptme/tools/python.py

@@ -120,7 +120,7 @@ def execute_python(
 
 
 @functools.lru_cache
-def get_installed_python_libraries() -> set[str]:
+def get_installed_python_libraries() -> list[str]:
     """Check if a select list of Python libraries are installed."""
     candidates = [
         "numpy",
@@ -137,7 +137,7 @@ def get_installed_python_libraries() -> set[str]:
         if importlib.util.find_spec(candidate):
             installed.add(candidate)
 
-    return installed
+    return list(sorted(installed))
 
 
 def get_functions():

gptme/tools/shell.py

@@ -44,7 +44,7 @@
 
 
 shell_programs_str = "\n".join(
-    f"- {prog}" for prog in get_installed_programs(candidates)
+    f"- {prog}" for prog in sorted(get_installed_programs(candidates))
 )
 is_macos = sys.platform == "darwin"
 

gptme/util/__init__.py

@@ -37,7 +37,7 @@ def get_tokenizer(model: str):
     except KeyError:
         global _warned_models
         if model not in _warned_models:
-            logger.warning(
+            logger.info(
                 f"No tokenizer for '{model}'. Using tiktoken cl100k_base. Use results only as estimates."
             )
             _warned_models |= {model}